Remove unused code & refactor and simplify event load timing

src/ripple/core/Job.h

@@ -142,7 +142,7 @@ private:
     JobType                     mType;
     std::uint64_t               mJobIndex;
     std::function <void (Job&)> mJob;
-    LoadEvent::pointer          m_loadEvent;
+    std::shared_ptr<LoadEvent>  m_loadEvent;
     std::string                 mName;
     clock_type::time_point m_queue_time;
 };

src/ripple/core/JobQueue.h

@@ -150,11 +150,13 @@ public:
 
     // VFALCO TODO Rename these to newLoadEventMeasurement or something similar
     //             since they create the object.
-    LoadEvent::pointer getLoadEvent (JobType t, std::string const& name);
+    std::shared_ptr<LoadEvent>
+    getLoadEvent (JobType t, std::string const& name);
 
     // VFALCO TODO Why do we need two versions, one which returns a shared
     //             pointer and the other which returns an autoptr?
-    LoadEvent::autoptr getLoadEventAP (JobType t, std::string const& name);
+    std::unique_ptr <LoadEvent>
+    getLoadEventAP (JobType t, std::string const& name);
 
     /** Add multiple load events.
     */

src/ripple/core/LoadEvent.h

@@ -20,8 +20,9 @@
 #ifndef RIPPLE_CORE_LOADEVENT_H_INCLUDED
 #define RIPPLE_CORE_LOADEVENT_H_INCLUDED
 
-#include <ripple/beast/core/RelativeTime.h>
+#include <chrono>
 #include <memory>
+#include <string>
 
 namespace ripple {
 
@@ -34,52 +35,54 @@ class LoadMonitor;
 //
 class LoadEvent
 {
-public:
-    // VFALCO NOTE Why are these shared pointers? Wouldn't there be a
-    //             piece of lifetime-managed calling code that can simply own
-    //             the object?
-    //
-    //             Why both kinds of containers?
-    //
-    using pointer = std::shared_ptr <LoadEvent>;
-    using autoptr = std::unique_ptr <LoadEvent>;
-
 public:
     // VFALCO TODO remove the dependency on LoadMonitor. Is that possible?
     LoadEvent (LoadMonitor& monitor,
                std::string const& name,
                bool shouldStart);
+    LoadEvent(LoadEvent const&) = delete;
 
     ~LoadEvent ();
 
-    std::string const& name () const;
-    double getSecondsWaiting() const;
-    double getSecondsRunning() const;
-    double getSecondsTotal() const;
+    std::string const&
+    name () const;
+
+    // The time spent waiting.
+    std::chrono::steady_clock::duration
+    waitTime() const;
+
+    // The time spent running.
+    std::chrono::steady_clock::duration
+    runTime() const;
 
     // VFALCO TODO rename this to setName () or setLabel ()
     void reName (std::string const& name);
 
-    // Start the measurement. The constructor calls this automatically if
-    // shouldStart is true. If the operation is aborted, start() can be
-    // called again later.
-    //
+    // Start the measurement. If already started, then
+    // restart, assigning the elapsed time to the "waiting"
+    // state.
     void start ();
 
-    // Stops the measurement and reports the results. The time reported is
-    // measured from the last call to start.
-    //
+    // Stop the measurement and report the results. The
+    // time reported is measured from the last call to
+    // start.
     void stop ();
 
 private:
-    LoadMonitor& m_loadMonitor;
-    bool m_isRunning;
-    std::string m_name;
-    // VFALCO TODO Replace these with chrono
-    beast::RelativeTime m_timeStopped;
-    beast::RelativeTime m_timeStarted;
-    double m_secondsWaiting;
-    double m_secondsRunning;
+    LoadMonitor& monitor_;
+
+    // Represents our current state
+    bool running_;
+
+    // The name associated with this event, if any.
+    std::string name_;
+
+    // Represents the time we last transitioned states
+    std::chrono::steady_clock::time_point mark_;
+
+    // The time we spent waiting and running respectively
+    std::chrono::steady_clock::duration timeWaiting_;
+    std::chrono::steady_clock::duration timeRunning_;
 };
 
 } // ripple

src/ripple/core/LoadMonitor.h

@@ -37,10 +37,6 @@ public:
     explicit
     LoadMonitor (beast::Journal j);
 
-    void addCount ();
-
-    void addLatency (int latency);
-
     void addLoadSample (LoadEvent const& sample);
 
     void addSamples (int count, std::chrono::milliseconds latency);
@@ -65,13 +61,9 @@ public:
     bool isOver ();
 
 private:
-    static std::string printElapsed (double seconds);
-
     void update ();
 
-    using LockType = std::mutex;
-    using ScopedLockType = std::lock_guard <LockType>;
-    LockType mLock;
+    std::mutex mutex_;
 
     std::uint64_t mCounts;
     int           mLatencyEvents;

src/ripple/core/impl/JobQueue.cpp

@@ -189,7 +189,7 @@ JobQueue::setThreadCount (int c, bool const standaloneMode)
     m_workers.setNumberOfThreads (c);
 }
 
-LoadEvent::pointer
+std::shared_ptr<LoadEvent>
 JobQueue::getLoadEvent (JobType t, std::string const& name)
 {
     JobDataMap::iterator iter (m_jobData.find (t));
@@ -202,7 +202,7 @@ JobQueue::getLoadEvent (JobType t, std::string const& name)
         std::ref (iter-> second.load ()), name, true);
 }
 
-LoadEvent::autoptr
+std::unique_ptr<LoadEvent>
 JobQueue::getLoadEventAP (JobType t, std::string const& name)
 {
     JobDataMap::iterator iter (m_jobData.find (t));

src/ripple/core/impl/LoadEvent.cpp

@@ -21,79 +21,74 @@
 #include <ripple/core/LoadEvent.h>
 #include <ripple/core/LoadMonitor.h>
 #include <cassert>
+#include <iomanip>
 
 namespace ripple {
 
-LoadEvent::LoadEvent (LoadMonitor& monitor, std::string const& name, bool shouldStart)
-    : m_loadMonitor (monitor)
-    , m_isRunning (false)
-    , m_name (name)
-    , m_timeStopped (beast::RelativeTime::fromStartup())
-    , m_secondsWaiting (0)
-    , m_secondsRunning (0)
+LoadEvent::LoadEvent (
+        LoadMonitor& monitor,
+        std::string const& name,
+        bool shouldStart)
+    : monitor_ (monitor)
+    , running_ (shouldStart)
+    , name_ (name)
+    , mark_ { std::chrono::steady_clock::now() }
+    , timeWaiting_ {}
+    , timeRunning_ {}
 {
-    if (shouldStart)
-        start ();
 }
 
 LoadEvent::~LoadEvent ()
 {
-    if (m_isRunning)
+    if (running_)
         stop ();
 }
 
 std::string const& LoadEvent::name () const
 {
-    return m_name;
+    return name_;
 }
 
-double LoadEvent::getSecondsWaiting() const
+std::chrono::steady_clock::duration
+LoadEvent::waitTime() const
 {
-    return m_secondsWaiting;
+    return timeWaiting_;
 }
 
-double LoadEvent::getSecondsRunning() const
+std::chrono::steady_clock::duration
+LoadEvent::runTime() const
 {
-    return m_secondsRunning;
-}
-
-double LoadEvent::getSecondsTotal() const
-{
-    return m_secondsWaiting + m_secondsRunning;
+    return timeRunning_;
 }
 
 void LoadEvent::reName (std::string const& name)
 {
-    m_name = name;
+    name_ = name;
 }
 
 void LoadEvent::start ()
 {
-    beast::RelativeTime const currentTime (beast::RelativeTime::fromStartup());
+    auto const now = std::chrono::steady_clock::now();
 
-    // If we already called start, this call will replace the previous one.
-    if (m_isRunning)
-    {
-        m_secondsWaiting += (currentTime - m_timeStarted).inSeconds();
-    }
-    else
-    {
-        m_secondsWaiting += (currentTime - m_timeStopped).inSeconds();
-        m_isRunning = true;
-    }
-
-    m_timeStarted = currentTime;
+    // If we had already called start, this call will
+    // replace the previous one. Any time accumulated will
+    // be counted as "waiting".
+    timeWaiting_ += now - mark_;
+    mark_ = now;
+    running_ = true;
 }
 
 void LoadEvent::stop ()
 {
-    assert (m_isRunning);
+    assert (running_);
 
-    m_timeStopped = beast::RelativeTime::fromStartup();
-    m_secondsRunning += (m_timeStopped - m_timeStarted).inSeconds();
+    auto const now = std::chrono::steady_clock::now();
 
-    m_isRunning = false;
-    m_loadMonitor.addLoadSample (*this);
+    timeRunning_ += now - mark_;
+    mark_ = now;
+    running_ = false;
+
+    monitor_.addLoadSample (*this);
 }
 
 } // ripple

src/ripple/core/impl/LoadMonitor.cpp

@@ -20,6 +20,7 @@
 #include <BeastConfig.h>
 #include <ripple/basics/Log.h>
 #include <ripple/basics/UptimeTimer.h>
+#include <ripple/beast/clock/chrono_util.h>
 #include <ripple/core/LoadMonitor.h>
 
 namespace ripple {
@@ -66,9 +67,6 @@ LoadMonitor::LoadMonitor (beast::Journal j)
 void LoadMonitor::update ()
 {
     int now = UptimeTimer::getInstance ().getElapsedSeconds ();
-
-    // VFALCO TODO stop returning from the middle of functions.
-
     if (now == mLastUpdate) // current
         return;
 
@@ -104,73 +102,23 @@ void LoadMonitor::update ()
     while (mLastUpdate < now);
 }
 
-void LoadMonitor::addCount ()
+void LoadMonitor::addLoadSample (LoadEvent const& s)
 {
-    ScopedLockType sl (mLock);
+    using namespace std::chrono;
 
-    update ();
-    ++mCounts;
-}
+    auto const total = s.runTime() + s.waitTime();
+    // Don't include "jitter" as part of the latency
+    auto const latency = total < 2ms ? 0ms : round<milliseconds>(total);
 
-void LoadMonitor::addLatency (int latency)
-{
-    // VFALCO NOTE Why does 1 become 0?
-    if (latency == 1)
-        latency = 0;
-
-    ScopedLockType sl (mLock);
-
-    update ();
-
-    ++mLatencyEvents;
-    mLatencyMSAvg += latency;
-    mLatencyMSPeak += latency;
-
-    // Units are quarters of a millisecond
-    int const latencyPeak = mLatencyEvents * latency * 4;
-
-    if (mLatencyMSPeak < latencyPeak)
-        mLatencyMSPeak = latencyPeak;
-}
-
-std::string LoadMonitor::printElapsed (double seconds)
-{
-    std::stringstream ss;
-    ss << (std::size_t (seconds * 1000 + 0.5)) << " ms";
-    return ss.str();
-}
-
-void LoadMonitor::addLoadSample (LoadEvent const& sample)
-{
-    std::string const& name (sample.name());
-    beast::RelativeTime const latency (sample.getSecondsTotal());
-
-    if (latency.inSeconds() > 0.5)
+    if (latency > 500ms)
     {
-        auto mj = latency.inSeconds() > 1.0 ? j_.warn() : j_.info();
-        JLOG (mj)
-            << "Job: " << name << " ExecutionTime: " << printElapsed (sample.getSecondsRunning()) <<
-            " WaitingTime: " << printElapsed (sample.getSecondsWaiting());
+        auto mj = (latency > 1s) ? j_.warn() : j_.info();
+        JLOG (mj) << "Job: " << s.name() <<
+            " run: " << round<milliseconds>(s.runTime()).count() << "ms" <<
+            " wait: " << round<milliseconds>(s.waitTime()).count() << "ms";
     }
 
-    // VFALCO NOTE Why does 1 become 0?
-    std::size_t latencyMilliseconds (latency.inMilliseconds());
-    if (latencyMilliseconds == 1)
-        latencyMilliseconds = 0;
-
-    ScopedLockType sl (mLock);
-
-    update ();
-    ++mCounts;
-    ++mLatencyEvents;
-    mLatencyMSAvg += latencyMilliseconds;
-    mLatencyMSPeak += latencyMilliseconds;
-
-    // VFALCO NOTE Why are we multiplying by 4?
-    int const latencyPeak = mLatencyEvents * latencyMilliseconds * 4;
-
-    if (mLatencyMSPeak < latencyPeak)
-        mLatencyMSPeak = latencyPeak;
+    addSamples (1, latency);
 }
 
 /* Add multiple samples
@@ -179,7 +127,7 @@ void LoadMonitor::addLoadSample (LoadEvent const& sample)
 */
 void LoadMonitor::addSamples (int count, std::chrono::milliseconds latency)
 {
-    ScopedLockType sl (mLock);
+    std::lock_guard<std::mutex> sl (mutex_);
 
     update ();
     mCounts += count;
@@ -207,7 +155,7 @@ bool LoadMonitor::isOverTarget (std::uint64_t avg, std::uint64_t peak)
 
 bool LoadMonitor::isOver ()
 {
-    ScopedLockType sl (mLock);
+    std::lock_guard<std::mutex> sl (mutex_);
 
     update ();
 
@@ -221,7 +169,7 @@ LoadMonitor::Stats LoadMonitor::getStats ()
 {
     Stats stats;
 
-    ScopedLockType sl (mLock);
+    std::lock_guard<std::mutex> sl (mutex_);
 
     update ();