Add function call timing for all Application::sweep operations

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 <Application> ("TransactionMaster::sweep", __FILE__, __LINE__, boost::bind (
+        &TransactionMaster::sweep, &mMasterTransaction));
+    //mMasterTransaction.sweep ();
+
+    logTimedCall <Application> ("NodeStore::sweep", __FILE__, __LINE__, boost::bind (
+        &NodeStore::sweep, m_nodeStore.get ()));
+    //m_nodeStore->sweep ();
+
+    logTimedCall <Application> ("LedgerMaster::sweep", __FILE__, __LINE__, boost::bind (
+        &LedgerMaster::sweep, &mLedgerMaster));
+    //mLedgerMaster.sweep ();
+
+    logTimedCall <Application> ("TempNodeCache::sweep", __FILE__, __LINE__, boost::bind (
+        &NodeCache::sweep, &mTempNodeCache));
+    //mTempNodeCache.sweep ();
+
+    logTimedCall <Application> ("Validations::sweep", __FILE__, __LINE__, boost::bind (
+        &IValidations::sweep, mValidations.get ()));
+    //mValidations->sweep ();
+
+    logTimedCall <Application> ("InboundLedgers::sweep", __FILE__, __LINE__, boost::bind (
+        &InboundLedgers::sweep, &getInboundLedgers ()));
+    //getInboundLedgers ().sweep ();
+
+    logTimedCall <Application> ("SLECache::sweep", __FILE__, __LINE__, boost::bind (
+        &SLECache::sweep, &mSLECache));
+    //mSLECache.sweep ();
+
+    logTimedCall <Application> ("AcceptedLedger::sweep", __FILE__, __LINE__,
+        &AcceptedLedger::sweep);
+    //AcceptedLedger::sweep (); // VFALCO NOTE AcceptedLedger is/has a singleton?
+
+    logTimedCall <Application> ("SHAMap::sweep", __FILE__, __LINE__,
+        &SHAMap::sweep);
+    //SHAMap::sweep (); // VFALCO NOTE SHAMap is/has a singleton?
+
+    logTimedCall <Application> ("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));

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 ();
+}

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 <uint256, Transaction, UptimeTimerAdapter> mCache;

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"

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 <boost::unordered_map <Key, Value> >
     }
 };
 
+/** 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 <int> ((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 <typename PartitionKey, typename Object>
 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 <int> ((seconds * 10 + 0.5) / 10);
-
         Log (severity, LogPartition::get <PartitionKey> ()) <<
             objectDescription << " took "<<
-            String (seconds) <<
+            String (detail::cleanElapsed (seconds)) <<
             " seconds to destroy";
     }
 }
 
+//------------------------------------------------------------------------------
+
+/** Log a timed function call if the time exceeds a threshold. */
+template <typename PartitionKey, typename Function>
+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 <PartitionKey> ()) <<
+            description << " took "<<
+            String (detail::cleanElapsed (seconds)) <<
+            " seconds to execute at " <<
+                Debug::getSourceLocation (fileName, lineNumber);
+    }
+}
+
 #endif