From b2e6b7f76fb6d6e6d063c0cee60085f3480b40cf Mon Sep 17 00:00:00 2001 From: Graydon Hoare Date: Wed, 24 Jul 2019 11:09:27 -0700 Subject: [PATCH 1/3] util: add CachedLogLevel helper to alleviate frequent log-level lookups. --- src/util/Logging.h | 47 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 47 insertions(+) diff --git a/src/util/Logging.h b/src/util/Logging.h index e116f886e2..81fb8c3688 100644 --- a/src/util/Logging.h +++ b/src/util/Logging.h @@ -42,4 +42,51 @@ class Logging static std::array const kPartitionNames; }; + +// Local wrapper that caches (for a fixed number of lookups) global log-level +// state queries, to avoid taking the global mutex and doing a std::map lookup +// every time you want to check whether a given log level is enabled. Typically +// you want to use this for log-level queries at TRACE level if they are showing +// up in profiles. + +class CachedLogLevel +{ + size_t mQueryFreq; + size_t mQueryCount; + std::string mPartition; + el::Level mLastQueryAnswer; + + public: + CachedLogLevel(std::string const& partition, size_t queryFreq = 1000) + : mQueryFreq(queryFreq) + , mQueryCount(0) + , mPartition(partition) + , mLastQueryAnswer(Logging::getLogLevel(mPartition)) + { + } + + el::Level + getLevel() + { + if (++mQueryCount > mQueryFreq) + { + mLastQueryAnswer = Logging::getLogLevel(mPartition); + mQueryCount = 0; + } + return mLastQueryAnswer; + } + + bool + logDebug() + { + auto lev = getLevel(); + return lev == el::Level::Debug || lev == el::Level::Trace; + } + + bool + logTrace() + { + return getLevel() == el::Level::Trace; + } +}; } From 91de75ccb5d708e70b4ee947c92c16360abb1dfc Mon Sep 17 00:00:00 2001 From: Graydon Hoare Date: Wed, 24 Jul 2019 11:10:07 -0700 Subject: [PATCH 2/3] util: add Batch{Meter,Timer} helpers to alleviate frequent medida writes. --- lib/libmedida | 2 +- src/util/BatchMetrics.cpp | 64 +++++++++++++++++++++++++++++++++++++++ src/util/BatchMetrics.h | 64 +++++++++++++++++++++++++++++++++++++++ 3 files changed, 129 insertions(+), 1 deletion(-) create mode 100644 src/util/BatchMetrics.cpp create mode 100644 src/util/BatchMetrics.h diff --git a/lib/libmedida b/lib/libmedida index f0565cf505..3e451cba84 160000 --- a/lib/libmedida +++ b/lib/libmedida @@ -1 +1 @@ -Subproject commit f0565cf5055ac880a4a4f917a9a7f6fe5c692aa5 +Subproject commit 3e451cba84d53199f865bf0fad6daf1b31da1c84 diff --git a/src/util/BatchMetrics.cpp b/src/util/BatchMetrics.cpp new file mode 100644 index 0000000000..4cfc1ea5ed --- /dev/null +++ b/src/util/BatchMetrics.cpp @@ -0,0 +1,64 @@ +// Copyright 2019 Stellar Development Foundation and contributors. Licensed +// under the Apache License, Version 2.0. See the COPYING file at the root +// of this distribution or at http://www.apache.org/licenses/LICENSE-2.0 + +#include "util/BatchMetrics.h" + +#include "medida/meter.h" +#include "medida/timer.h" + +using namespace stellar; + +BatchMeter::BatchMeter(medida::Meter& m, size_t batchSz) + : mMeter(m), mBatchSz(batchSz), mCurrentCount(0) +{ +} + +void +BatchMeter::Mark(size_t n) +{ + mCurrentCount += n; + if (mCurrentCount > mBatchSz) + { + mMeter.Mark(mCurrentCount); + mCurrentCount = 0; + } +} + +size_t +BatchMeter::count() const +{ + return mMeter.count() + mCurrentCount; +} + +BatchTimerContext::BatchTimerContext(BatchTimer& timer) + : mTimer(timer), mStart(Clock::now()) +{ +} + +BatchTimerContext::~BatchTimerContext() +{ + mTimer.Update(Clock::now() - mStart); +} + +BatchTimer::BatchTimer(medida::Timer& timer, size_t batchSz) + : mTimer(timer), mBatchSz(batchSz) +{ +} + +void +BatchTimer::Update(std::chrono::nanoseconds duration) +{ + mBatch.emplace_back(duration); + if (mBatch.size() >= mBatchSz) + { + mTimer.Update(mBatch); + mBatch.clear(); + } +} + +BatchTimerContext +BatchTimer::TimeScope() +{ + return BatchTimerContext(*this); +} diff --git a/src/util/BatchMetrics.h b/src/util/BatchMetrics.h new file mode 100644 index 0000000000..88ee45f646 --- /dev/null +++ b/src/util/BatchMetrics.h @@ -0,0 +1,64 @@ +#pragma once + +// Copyright 2019 Stellar Development Foundation and contributors. Licensed +// under the Apache License, Version 2.0. See the COPYING file at the root +// of this distribution or at http://www.apache.org/licenses/LICENSE-2.0 + +#include +#include +#include + +namespace medida +{ +class Timer; +class Meter; +class Counter; +} + +namespace stellar +{ + +// Wrapper around medida meter type to batch updates. Use this when you are +// seeing a medida meter itself showing up in a profile: it's being updated too +// quickly. Medida happens to be threadsafe and use atomic operations for +// counters, hitting it even a few hundred times a second can start to be +// noticable. + +class BatchMeter +{ + medida::Meter& mMeter; + size_t mBatchSz; + size_t mCurrentCount; + + public: + BatchMeter(medida::Meter& m, size_t batchSz = 100); + void Mark(size_t n = 1); + size_t count() const; +}; + +// Same, but for medida timer type. + +class BatchTimer; +class BatchTimerContext +{ + using Clock = std::chrono::high_resolution_clock; + BatchTimer& mTimer; + Clock::time_point mStart; + + public: + BatchTimerContext(BatchTimer& timer); + ~BatchTimerContext(); +}; + +class BatchTimer +{ + medida::Timer& mTimer; + size_t mBatchSz; + std::vector mBatch; + + public: + BatchTimer(medida::Timer& timer, size_t batchSz = 100); + void Update(std::chrono::nanoseconds duration); + BatchTimerContext TimeScope(); +}; +} From 7788ad857a1234fafa9ab331ccd69909b66f0bdb Mon Sep 17 00:00:00 2001 From: Graydon Hoare Date: Wed, 24 Jul 2019 10:58:10 -0700 Subject: [PATCH 3/3] Use batch log-level lookups and metric writes in various hot paths. --- src/herder/HerderImpl.h | 11 +++-- src/herder/HerderSCPDriver.cpp | 2 +- src/herder/HerderSCPDriver.h | 13 ++--- src/ledger/LedgerManagerImpl.h | 3 +- src/overlay/LoadManager.cpp | 45 +++++++++-------- src/overlay/LoadManager.h | 13 +++-- src/overlay/OverlayMetrics.h | 90 ++++++++++++++++++---------------- src/overlay/Peer.cpp | 23 +++++---- src/overlay/Peer.h | 2 + src/overlay/TCPPeer.cpp | 9 ++-- 10 files changed, 118 insertions(+), 93 deletions(-) diff --git a/src/herder/HerderImpl.h b/src/herder/HerderImpl.h index 4c833b2ca6..5b8d606056 100644 --- a/src/herder/HerderImpl.h +++ b/src/herder/HerderImpl.h @@ -9,6 +9,7 @@ #include "herder/PendingEnvelopes.h" #include "herder/TransactionQueue.h" #include "herder/Upgrades.h" +#include "util/BatchMetrics.h" #include "util/Timer.h" #include "util/XDROperators.h" #include @@ -173,18 +174,18 @@ class HerderImpl : public Herder struct SCPMetrics { - medida::Meter& mLostSync; + BatchMeter mLostSync; - medida::Meter& mEnvelopeEmit; - medida::Meter& mEnvelopeReceive; + BatchMeter mEnvelopeEmit; + BatchMeter mEnvelopeReceive; // Counters for things reached-through the // SCP maps: Slots and Nodes medida::Counter& mCumulativeStatements; // envelope signature verification - medida::Meter& mEnvelopeValidSig; - medida::Meter& mEnvelopeInvalidSig; + BatchMeter mEnvelopeValidSig; + BatchMeter mEnvelopeInvalidSig; SCPMetrics(Application& app); }; diff --git a/src/herder/HerderSCPDriver.cpp b/src/herder/HerderSCPDriver.cpp index 92b4e570a2..afa3c26d87 100644 --- a/src/herder/HerderSCPDriver.cpp +++ b/src/herder/HerderSCPDriver.cpp @@ -923,7 +923,7 @@ HerderSCPDriver::recordSCPExecutionMetrics(uint64_t slotIndex) mPrepareTimeout.Update(SCPTiming.mPrepareTimeoutCount); auto recordTiming = [&](VirtualClock::time_point start, - VirtualClock::time_point end, medida::Timer& timer, + VirtualClock::time_point end, BatchTimer& timer, std::string const& logStr) { auto delta = std::chrono::duration_cast(end - start); diff --git a/src/herder/HerderSCPDriver.h b/src/herder/HerderSCPDriver.h index 359637ae1e..a10f4d681a 100644 --- a/src/herder/HerderSCPDriver.h +++ b/src/herder/HerderSCPDriver.h @@ -7,6 +7,7 @@ #include "herder/Herder.h" #include "herder/TxSetFrame.h" #include "scp/SCPDriver.h" +#include "util/BatchMetrics.h" #include "xdr/Stellar-ledger.h" namespace medida @@ -153,17 +154,17 @@ class HerderSCPDriver : public SCPDriver struct SCPMetrics { - medida::Meter& mEnvelopeSign; + BatchMeter mEnvelopeSign; - medida::Meter& mValueValid; - medida::Meter& mValueInvalid; + BatchMeter mValueValid; + BatchMeter mValueInvalid; // listeners - medida::Meter& mCombinedCandidates; + BatchMeter mCombinedCandidates; // Timers for nomination and ballot protocols - medida::Timer& mNominateToPrepare; - medida::Timer& mPrepareToExternalize; + BatchTimer mNominateToPrepare; + BatchTimer mPrepareToExternalize; SCPMetrics(Application& app); }; diff --git a/src/ledger/LedgerManagerImpl.h b/src/ledger/LedgerManagerImpl.h index 7d4b393430..29a3dae618 100644 --- a/src/ledger/LedgerManagerImpl.h +++ b/src/ledger/LedgerManagerImpl.h @@ -10,6 +10,7 @@ #include "ledger/SyncingLedgerChain.h" #include "main/PersistentState.h" #include "transactions/TransactionFrame.h" +#include "util/BatchMetrics.h" #include "xdr/Stellar-ledger.h" #include @@ -41,7 +42,7 @@ class LedgerManagerImpl : public LedgerManager Application& mApp; private: - medida::Timer& mTransactionApply; + BatchTimer mTransactionApply; medida::Histogram& mTransactionCount; medida::Histogram& mOperationCount; medida::Counter& mInternalErrorCount; diff --git a/src/overlay/LoadManager.cpp b/src/overlay/LoadManager.cpp index 12098b3fb8..00ab3e8f82 100644 --- a/src/overlay/LoadManager.cpp +++ b/src/overlay/LoadManager.cpp @@ -70,9 +70,12 @@ LoadManager::reportLoads(std::map const& peers, CLOG(INFO, "Overlay") << fmt::format( "{:>10s} {:>10s} {:>10s} {:>10s} {:>10d}", app.getConfig().toShortString(peer.first), - timeMag(static_cast(cost->mTimeSpent.one_minute_rate())), - byteMag(static_cast(cost->mBytesSend.one_minute_rate())), - byteMag(static_cast(cost->mBytesRecv.one_minute_rate())), + timeMag( + static_cast(cost->mTimeSpentBase.one_minute_rate())), + byteMag( + static_cast(cost->mBytesSendBase.one_minute_rate())), + byteMag( + static_cast(cost->mBytesRecvBase.one_minute_rate())), cost->mSQLQueries.count()); } CLOG(INFO, "Overlay") << ""; @@ -134,10 +137,14 @@ LoadManager::maybeShedExcessLoad(Application& app) } LoadManager::PeerCosts::PeerCosts() - : mTimeSpent("nanoseconds") - , mBytesSend("byte") - , mBytesRecv("byte") - , mSQLQueries("query") + : mTimeSpentBase("nanoseconds") + , mBytesSendBase("byte") + , mBytesRecvBase("byte") + , mSQLQueriesBase("query") + , mTimeSpent(mTimeSpentBase) + , mBytesSend(mBytesSendBase) + , mBytesRecv(mBytesRecvBase) + , mSQLQueries(mSQLQueriesBase) { } @@ -145,12 +152,13 @@ bool LoadManager::PeerCosts::isLessThan( std::shared_ptr other) { - double ownRates[4] = { - mTimeSpent.one_minute_rate(), mBytesSend.one_minute_rate(), - mBytesRecv.one_minute_rate(), static_cast(mSQLQueries.count())}; - double otherRates[4] = {other->mTimeSpent.one_minute_rate(), - other->mBytesSend.one_minute_rate(), - other->mBytesRecv.one_minute_rate(), + double ownRates[4] = {mTimeSpentBase.one_minute_rate(), + mBytesSendBase.one_minute_rate(), + mBytesRecvBase.one_minute_rate(), + static_cast(mSQLQueries.count())}; + double otherRates[4] = {other->mTimeSpentBase.one_minute_rate(), + other->mBytesSendBase.one_minute_rate(), + other->mBytesRecvBase.one_minute_rate(), static_cast(other->mSQLQueries.count())}; return std::lexicographical_compare(ownRates, ownRates + 4, otherRates, otherRates + 4); @@ -184,18 +192,15 @@ LoadManager::PeerContext::~PeerContext() { if (!isZero(mNode.ed25519())) { + auto& metrics = mApp.getOverlayManager().getOverlayMetrics(); auto pc = mApp.getOverlayManager().getLoadManager().getPeerCosts(mNode); auto time = std::chrono::duration_cast( mApp.getClock().now() - mWorkStart); - auto send = - mApp.getOverlayManager().getOverlayMetrics().mByteWrite.count() - - mBytesSendStart; - auto recv = - mApp.getOverlayManager().getOverlayMetrics().mByteRead.count() - - mBytesRecvStart; + auto send = metrics.mByteWrite.count() - mBytesSendStart; + auto recv = metrics.mByteRead.count() - mBytesRecvStart; auto query = (mApp.getDatabase().getQueryMeter().count() - mSQLQueriesStart); - if (Logging::logTrace("Overlay")) + if (metrics.mLogLevel.logTrace()) CLOG(TRACE, "Overlay") << "Debiting peer " << mApp.getConfig().toShortString(mNode) << " time:" << timeMag(time.count()) diff --git a/src/overlay/LoadManager.h b/src/overlay/LoadManager.h index f5c7e60123..c4280cae4f 100644 --- a/src/overlay/LoadManager.h +++ b/src/overlay/LoadManager.h @@ -6,6 +6,7 @@ #include "crypto/SecretKey.h" #include "overlay/Peer.h" +#include "util/BatchMetrics.h" #include "util/HashOfHash.h" #include "util/lrucache.hpp" #include "xdr/Stellar-types.h" @@ -48,10 +49,14 @@ class LoadManager { PeerCosts(); bool isLessThan(std::shared_ptr other); - medida::Meter mTimeSpent; - medida::Meter mBytesSend; - medida::Meter mBytesRecv; - medida::Meter mSQLQueries; + medida::Meter mTimeSpentBase; + medida::Meter mBytesSendBase; + medida::Meter mBytesRecvBase; + medida::Meter mSQLQueriesBase; + BatchMeter mTimeSpent; + BatchMeter mBytesSend; + BatchMeter mBytesRecv; + BatchMeter mSQLQueries; }; std::shared_ptr getPeerCosts(NodeID const& peer); diff --git a/src/overlay/OverlayMetrics.h b/src/overlay/OverlayMetrics.h index f0e8a809c1..9ffe8eefa5 100644 --- a/src/overlay/OverlayMetrics.h +++ b/src/overlay/OverlayMetrics.h @@ -9,6 +9,9 @@ // tabulated at a per-peer level for purposes of identifying and // disconnecting overloading peers, see LoadManager for details. +#include "util/BatchMetrics.h" +#include "util/Logging.h" + namespace medida { class Timer; @@ -24,55 +27,56 @@ class Application; struct OverlayMetrics { OverlayMetrics(Application& app); - medida::Meter& mMessageRead; - medida::Meter& mMessageWrite; - medida::Meter& mByteRead; - medida::Meter& mByteWrite; - medida::Meter& mErrorRead; - medida::Meter& mErrorWrite; - medida::Meter& mTimeoutIdle; - medida::Meter& mTimeoutStraggler; + CachedLogLevel mLogLevel{"Overlay"}; + BatchMeter mMessageRead; + BatchMeter mMessageWrite; + BatchMeter mByteRead; + BatchMeter mByteWrite; + BatchMeter mErrorRead; + BatchMeter mErrorWrite; + BatchMeter mTimeoutIdle; + BatchMeter mTimeoutStraggler; - medida::Timer& mRecvErrorTimer; - medida::Timer& mRecvHelloTimer; - medida::Timer& mRecvAuthTimer; - medida::Timer& mRecvDontHaveTimer; - medida::Timer& mRecvGetPeersTimer; - medida::Timer& mRecvPeersTimer; - medida::Timer& mRecvGetTxSetTimer; - medida::Timer& mRecvTxSetTimer; - medida::Timer& mRecvTransactionTimer; - medida::Timer& mRecvGetSCPQuorumSetTimer; - medida::Timer& mRecvSCPQuorumSetTimer; - medida::Timer& mRecvSCPMessageTimer; - medida::Timer& mRecvGetSCPStateTimer; + BatchTimer mRecvErrorTimer; + BatchTimer mRecvHelloTimer; + BatchTimer mRecvAuthTimer; + BatchTimer mRecvDontHaveTimer; + BatchTimer mRecvGetPeersTimer; + BatchTimer mRecvPeersTimer; + BatchTimer mRecvGetTxSetTimer; + BatchTimer mRecvTxSetTimer; + BatchTimer mRecvTransactionTimer; + BatchTimer mRecvGetSCPQuorumSetTimer; + BatchTimer mRecvSCPQuorumSetTimer; + BatchTimer mRecvSCPMessageTimer; + BatchTimer mRecvGetSCPStateTimer; - medida::Timer& mRecvSCPPrepareTimer; - medida::Timer& mRecvSCPConfirmTimer; - medida::Timer& mRecvSCPNominateTimer; - medida::Timer& mRecvSCPExternalizeTimer; + BatchTimer mRecvSCPPrepareTimer; + BatchTimer mRecvSCPConfirmTimer; + BatchTimer mRecvSCPNominateTimer; + BatchTimer mRecvSCPExternalizeTimer; - medida::Meter& mSendErrorMeter; - medida::Meter& mSendHelloMeter; - medida::Meter& mSendAuthMeter; - medida::Meter& mSendDontHaveMeter; - medida::Meter& mSendGetPeersMeter; - medida::Meter& mSendPeersMeter; - medida::Meter& mSendGetTxSetMeter; - medida::Meter& mSendTransactionMeter; - medida::Meter& mSendTxSetMeter; - medida::Meter& mSendGetSCPQuorumSetMeter; - medida::Meter& mSendSCPQuorumSetMeter; - medida::Meter& mSendSCPMessageSetMeter; - medida::Meter& mSendGetSCPStateMeter; + BatchMeter mSendErrorMeter; + BatchMeter mSendHelloMeter; + BatchMeter mSendAuthMeter; + BatchMeter mSendDontHaveMeter; + BatchMeter mSendGetPeersMeter; + BatchMeter mSendPeersMeter; + BatchMeter mSendGetTxSetMeter; + BatchMeter mSendTransactionMeter; + BatchMeter mSendTxSetMeter; + BatchMeter mSendGetSCPQuorumSetMeter; + BatchMeter mSendSCPQuorumSetMeter; + BatchMeter mSendSCPMessageSetMeter; + BatchMeter mSendGetSCPStateMeter; - medida::Meter& mMessagesBroadcast; + BatchMeter mMessagesBroadcast; medida::Counter& mPendingPeersSize; medida::Counter& mAuthenticatedPeersSize; - medida::Meter& mUniqueFloodBytesRecv; - medida::Meter& mDuplicateFloodBytesRecv; - medida::Meter& mUniqueFetchBytesRecv; - medida::Meter& mDuplicateFetchBytesRecv; + BatchMeter mUniqueFloodBytesRecv; + BatchMeter mDuplicateFloodBytesRecv; + BatchMeter mUniqueFetchBytesRecv; + BatchMeter mDuplicateFetchBytesRecv; }; } diff --git a/src/overlay/Peer.cpp b/src/overlay/Peer.cpp index e83fbcee75..c9dbfd2653 100644 --- a/src/overlay/Peer.cpp +++ b/src/overlay/Peer.cpp @@ -51,6 +51,7 @@ Peer::Peer(Application& app, PeerRole role) , mLastRead(app.getClock().now()) , mLastWrite(app.getClock().now()) , mLastEmpty(app.getClock().now()) + , mLogLevel(getOverlayMetrics().mLogLevel) { auto bytes = randomBytes(mSendNonce.size()); std::copy(bytes.begin(), bytes.end(), mSendNonce.begin()); @@ -230,7 +231,7 @@ Peer::sendGetTxSet(uint256 const& setID) void Peer::sendGetQuorumSet(uint256 const& setID) { - if (Logging::logTrace("Overlay")) + if (mLogLevel.logTrace()) CLOG(TRACE, "Overlay") << "Get quorum set: " << hexAbbrev(setID); StellarMessage newMsg; @@ -243,7 +244,8 @@ Peer::sendGetQuorumSet(uint256 const& setID) void Peer::sendGetPeers() { - CLOG(TRACE, "Overlay") << "Get peers"; + if (mLogLevel.logTrace()) + CLOG(TRACE, "Overlay") << "Get peers"; StellarMessage newMsg; newMsg.type(GET_PEERS); @@ -254,7 +256,8 @@ Peer::sendGetPeers() void Peer::sendGetScpState(uint32 ledgerSeq) { - CLOG(TRACE, "Overlay") << "Get SCP State for " << ledgerSeq; + if (mLogLevel.logTrace()) + CLOG(TRACE, "Overlay") << "Get SCP State for " << ledgerSeq; StellarMessage newMsg; newMsg.type(GET_SCP_STATE); @@ -352,7 +355,7 @@ msgSummary(StellarMessage const& msg) void Peer::sendMessage(StellarMessage const& msg) { - if (Logging::logTrace("Overlay")) + if (mLogLevel.logTrace()) CLOG(TRACE, "Overlay") << "(" << mApp.getConfig().toShortString( @@ -426,7 +429,8 @@ Peer::recvMessage(xdr::msg_ptr const& msg) LoadManager::PeerContext loadCtx(mApp, mPeerID); - CLOG(TRACE, "Overlay") << "received xdr::msg_ptr"; + if (mLogLevel.logTrace()) + CLOG(TRACE, "Overlay") << "received xdr::msg_ptr"; try { AuthenticatedMessage am; @@ -501,7 +505,7 @@ Peer::recvMessage(StellarMessage const& stellarMsg) return; } - if (Logging::logTrace("Overlay")) + if (mLogLevel.logTrace()) CLOG(TRACE, "Overlay") << "(" << mApp.getConfig().toShortString( @@ -687,7 +691,7 @@ Peer::recvGetSCPQuorumSet(StellarMessage const& msg) } else { - if (Logging::logTrace("Overlay")) + if (mLogLevel.logTrace()) CLOG(TRACE, "Overlay") << "No quorum set: " << hexAbbrev(msg.qSetHash()); sendDontHave(SCP_QUORUMSET, msg.qSetHash()); @@ -705,7 +709,7 @@ void Peer::recvSCPMessage(StellarMessage const& msg) { SCPEnvelope const& envelope = msg.envelope(); - if (Logging::logTrace("Overlay")) + if (mLogLevel.logTrace()) CLOG(TRACE, "Overlay") << "recvSCPMessage node: " << mApp.getConfig().toShortString(msg.envelope().statement.nodeID); @@ -732,7 +736,8 @@ void Peer::recvGetSCPState(StellarMessage const& msg) { uint32 seq = msg.getSCPLedgerSeq(); - CLOG(TRACE, "Overlay") << "get SCP State " << seq; + if (mLogLevel.logTrace()) + CLOG(TRACE, "Overlay") << "get SCP State " << seq; mApp.getHerder().sendSCPStateToPeer(seq, shared_from_this()); } diff --git a/src/overlay/Peer.h b/src/overlay/Peer.h index f154d1f35d..2be7475aa0 100644 --- a/src/overlay/Peer.h +++ b/src/overlay/Peer.h @@ -8,6 +8,7 @@ #include "database/Database.h" #include "overlay/PeerBareAddress.h" #include "overlay/StellarXDR.h" +#include "util/Logging.h" #include "util/NonCopyable.h" #include "util/Timer.h" #include "xdrpp/message.h" @@ -89,6 +90,7 @@ class Peer : public std::enable_shared_from_this, VirtualClock::time_point mLastEmpty; OverlayMetrics& getOverlayMetrics(); + CachedLogLevel& mLogLevel; bool shouldAbort() const; void recvMessage(StellarMessage const& msg); diff --git a/src/overlay/TCPPeer.cpp b/src/overlay/TCPPeer.cpp index e7dfa11d1e..a84b9635b4 100644 --- a/src/overlay/TCPPeer.cpp +++ b/src/overlay/TCPPeer.cpp @@ -140,7 +140,7 @@ TCPPeer::sendMessage(xdr::msg_ptr&& xdrBytes) return; } - if (Logging::logTrace("Overlay")) + if (mLogLevel.logTrace()) CLOG(TRACE, "Overlay") << "TCPPeer:sendMessage to " << toString(); assertThreadIsMain(); @@ -326,14 +326,15 @@ TCPPeer::startRead() assert(self->mIncomingHeader.size() == 0); - if (Logging::logTrace("Overlay")) + bool logTrace = mLogLevel.logTrace(); + if (logTrace) CLOG(TRACE, "Overlay") << "TCPPeer::startRead to " << self->toString(); self->mIncomingHeader.resize(4); asio::async_read(*(self->mSocket.get()), asio::buffer(self->mIncomingHeader), - [self](asio::error_code ec, std::size_t length) { - if (Logging::logTrace("Overlay")) + [self, logTrace](asio::error_code ec, std::size_t length) { + if (logTrace) CLOG(TRACE, "Overlay") << "TCPPeer::startRead calledback " << ec << " length:" << length;