From 4ececd02041c0c0503dbc23786fbd6ef15efed8c Mon Sep 17 00:00:00 2001 From: Vinnie Falco Date: Fri, 23 Aug 2013 09:43:11 -0700 Subject: [PATCH] Add function call timing for all Application::sweep operations --- Builds/VisualStudio2012/RippleD.vcxproj | 2 +- .../VisualStudio2012/RippleD.vcxproj.filters | 2 +- .../ripple_app/main/ripple_Application.cpp | 50 +++++++++++++++---- modules/ripple_app/tx/TransactionMaster.cpp | 9 +++- modules/ripple_app/tx/TransactionMaster.h | 5 +- modules/ripple_basics/ripple_basics.h | 2 +- ..._TimedDestroy.h => ripple_LoggedTimings.h} | 44 ++++++++++++---- 7 files changed, 85 insertions(+), 29 deletions(-) rename modules/ripple_basics/utility/{ripple_TimedDestroy.h => ripple_LoggedTimings.h} (58%) diff --git a/Builds/VisualStudio2012/RippleD.vcxproj b/Builds/VisualStudio2012/RippleD.vcxproj index 203b29f495..d3d3b080a2 100644 --- a/Builds/VisualStudio2012/RippleD.vcxproj +++ b/Builds/VisualStudio2012/RippleD.vcxproj @@ -1512,7 +1512,7 @@ - + diff --git a/Builds/VisualStudio2012/RippleD.vcxproj.filters b/Builds/VisualStudio2012/RippleD.vcxproj.filters index 470020139f..048232b075 100644 --- a/Builds/VisualStudio2012/RippleD.vcxproj.filters +++ b/Builds/VisualStudio2012/RippleD.vcxproj.filters @@ -1691,7 +1691,7 @@ [1] Ripple\ripple_app\boost - + [1] Ripple\ripple_basics\utility diff --git a/modules/ripple_app/main/ripple_Application.cpp b/modules/ripple_app/main/ripple_Application.cpp index f8c514fe85..ee96c6514a 100644 --- a/modules/ripple_app/main/ripple_Application.cpp +++ b/modules/ripple_app/main/ripple_Application.cpp @@ -776,16 +776,46 @@ void ApplicationImp::doSweep(Job& j) // have listeners register for "onSweep ()" notification. // - mMasterTransaction.sweep (); - m_nodeStore->sweep (); - mLedgerMaster.sweep (); - mTempNodeCache.sweep (); - mValidations->sweep (); - getInboundLedgers ().sweep (); - mSLECache.sweep (); - AcceptedLedger::sweep (); // VFALCO NOTE AcceptedLedger is/has a singleton? - SHAMap::sweep (); // VFALCO NOTE SHAMap is/has a singleton? - mNetOps->sweepFetchPack (); + logTimedCall ("TransactionMaster::sweep", __FILE__, __LINE__, boost::bind ( + &TransactionMaster::sweep, &mMasterTransaction)); + //mMasterTransaction.sweep (); + + logTimedCall ("NodeStore::sweep", __FILE__, __LINE__, boost::bind ( + &NodeStore::sweep, m_nodeStore.get ())); + //m_nodeStore->sweep (); + + logTimedCall ("LedgerMaster::sweep", __FILE__, __LINE__, boost::bind ( + &LedgerMaster::sweep, &mLedgerMaster)); + //mLedgerMaster.sweep (); + + logTimedCall ("TempNodeCache::sweep", __FILE__, __LINE__, boost::bind ( + &NodeCache::sweep, &mTempNodeCache)); + //mTempNodeCache.sweep (); + + logTimedCall ("Validations::sweep", __FILE__, __LINE__, boost::bind ( + &IValidations::sweep, mValidations.get ())); + //mValidations->sweep (); + + logTimedCall ("InboundLedgers::sweep", __FILE__, __LINE__, boost::bind ( + &InboundLedgers::sweep, &getInboundLedgers ())); + //getInboundLedgers ().sweep (); + + logTimedCall ("SLECache::sweep", __FILE__, __LINE__, boost::bind ( + &SLECache::sweep, &mSLECache)); + //mSLECache.sweep (); + + logTimedCall ("AcceptedLedger::sweep", __FILE__, __LINE__, + &AcceptedLedger::sweep); + //AcceptedLedger::sweep (); // VFALCO NOTE AcceptedLedger is/has a singleton? + + logTimedCall ("SHAMap::sweep", __FILE__, __LINE__, + &SHAMap::sweep); + //SHAMap::sweep (); // VFALCO NOTE SHAMap is/has a singleton? + + logTimedCall ("NetworkOPs::sweepFetchPack", __FILE__, __LINE__, boost::bind ( + &NetworkOPs::sweepFetchPack, mNetOps.get ())); + //mNetOps->sweepFetchPack (); + // VFALCO NOTE does the call to sweep() happen on another thread? mSweepTimer.expires_from_now (boost::posix_time::seconds (getConfig ().getSize (siSweepInterval))); mSweepTimer.async_wait (BIND_TYPE (&ApplicationImp::sweep, this)); diff --git a/modules/ripple_app/tx/TransactionMaster.cpp b/modules/ripple_app/tx/TransactionMaster.cpp index 133fac7cab..cdc024fb02 100644 --- a/modules/ripple_app/tx/TransactionMaster.cpp +++ b/modules/ripple_app/tx/TransactionMaster.cpp @@ -12,7 +12,8 @@ #define CACHED_TRANSACTION_AGE 1800 #endif -TransactionMaster::TransactionMaster () : mCache ("TransactionCache", CACHED_TRANSACTION_NUM, CACHED_TRANSACTION_AGE) +TransactionMaster::TransactionMaster () + : mCache ("TransactionCache", CACHED_TRANSACTION_NUM, CACHED_TRANSACTION_AGE) { ; } @@ -92,4 +93,8 @@ bool TransactionMaster::canonicalize (Transaction::pointer& txn) return false; } -// vim:ts=4 + +void TransactionMaster::sweep (void) +{ + mCache.sweep (); +} diff --git a/modules/ripple_app/tx/TransactionMaster.h b/modules/ripple_app/tx/TransactionMaster.h index 4bfce624bc..1c66356318 100644 --- a/modules/ripple_app/tx/TransactionMaster.h +++ b/modules/ripple_app/tx/TransactionMaster.h @@ -21,10 +21,7 @@ public: // return value: true = we had the transaction already bool inLedger (uint256 const& hash, uint32 ledger); bool canonicalize (Transaction::pointer& txn); - void sweep (void) - { - mCache.sweep (); - } + void sweep (void); private: TaggedCache mCache; diff --git a/modules/ripple_basics/ripple_basics.h b/modules/ripple_basics/ripple_basics.h index 72526365c9..564e645350 100644 --- a/modules/ripple_basics/ripple_basics.h +++ b/modules/ripple_basics/ripple_basics.h @@ -90,7 +90,7 @@ using namespace beast; #include "utility/ripple_Sustain.h" #include "utility/ripple_ThreadName.h" #include "utility/ripple_Time.h" -#include "utility/ripple_TimedDestroy.h" +#include "utility/ripple_LoggedTimings.h" #include "utility/ripple_UptimeTimer.h" #include "types/ripple_UInt256.h" diff --git a/modules/ripple_basics/utility/ripple_TimedDestroy.h b/modules/ripple_basics/utility/ripple_LoggedTimings.h similarity index 58% rename from modules/ripple_basics/utility/ripple_TimedDestroy.h rename to modules/ripple_basics/utility/ripple_LoggedTimings.h index 4ac0deb5e2..ddc933f4bc 100644 --- a/modules/ripple_basics/utility/ripple_TimedDestroy.h +++ b/modules/ripple_basics/utility/ripple_LoggedTimings.h @@ -4,8 +4,8 @@ */ //============================================================================== -#ifndef RIPPLE_TIMEDDESTROY_H_INCLUDED -#define RIPPLE_TIMEDDESTROY_H_INCLUDED +#ifndef RIPPLE_LOGGEDTIMINGS_H_INCLUDED +#define RIPPLE_LOGGEDTIMINGS_H_INCLUDED namespace detail { @@ -44,6 +44,14 @@ struct Destroyer > } }; +/** Cleans up an elaspsed time so it prints nicely */ +inline double cleanElapsed (double seconds) noexcept +{ + if (seconds >= 10) + return std::floor (seconds + 0.5); + + return static_cast ((seconds * 10 + 0.5) / 10); +} } @@ -63,28 +71,44 @@ double timedDestroy (Object& object) Time::getHighResolutionTicks () - startTime); } -/** Log the destruction of an object if the time exceeds a threshold. +/** Log the timed destruction of an object if the time exceeds a threshold. */ template void logTimedDestroy ( Object& object, String objectDescription, double thresholdSeconds = 1) { - double seconds = timedDestroy (object); + double const seconds = timedDestroy (object); if (seconds > thresholdSeconds) { LogSeverity const severity = lsWARNING; - if (seconds >= 10) - seconds = std::floor (seconds + 0.5); - else - seconds = static_cast ((seconds * 10 + 0.5) / 10); - Log (severity, LogPartition::get ()) << objectDescription << " took "<< - String (seconds) << + String (detail::cleanElapsed (seconds)) << " seconds to destroy"; } } +//------------------------------------------------------------------------------ + +/** Log a timed function call if the time exceeds a threshold. */ +template +void logTimedCall (String description, char const* fileName, int lineNumber, + Function f, double thresholdSeconds = 1) +{ + double const seconds = measureFunctionCallTime (f); + + if (seconds > thresholdSeconds) + { + LogSeverity const severity = lsWARNING; + + Log (severity, LogPartition::get ()) << + description << " took "<< + String (detail::cleanElapsed (seconds)) << + " seconds to execute at " << + Debug::getSourceLocation (fileName, lineNumber); + } +} + #endif