Auto merge of #2198 - str4d:2139-timer, r=str4d

Improve mining metrics

Closes #2139.

src/gtest/test_metrics.cpp

@@ -4,9 +4,57 @@
 #include "utiltime.h"
 
 
+TEST(Metrics, AtomicTimer) {
+    AtomicTimer t;
+    SetMockTime(100);
+
+    EXPECT_FALSE(t.running());
+
+    t.start();
+    EXPECT_TRUE(t.running());
+
+    t.start();
+    EXPECT_TRUE(t.running());
+
+    t.stop();
+    EXPECT_TRUE(t.running());
+
+    t.stop();
+    EXPECT_FALSE(t.running());
+
+    // Additional calls to stop() are ignored.
+    t.stop();
+    EXPECT_FALSE(t.running());
+
+    t.start();
+    EXPECT_TRUE(t.running());
+
+    AtomicCounter c;
+    EXPECT_EQ(0, t.rate(c));
+
+    c.increment();
+    EXPECT_EQ(0, t.rate(c));
+
+    SetMockTime(101);
+    EXPECT_EQ(1, t.rate(c));
+
+    c.decrement();
+    EXPECT_EQ(0, t.rate(c));
+
+    SetMockTime(102);
+    EXPECT_EQ(0, t.rate(c));
+
+    c.increment();
+    EXPECT_EQ(0.5, t.rate(c));
+
+    t.stop();
+    EXPECT_FALSE(t.running());
+    EXPECT_EQ(0.5, t.rate(c));
+}
+
 TEST(Metrics, GetLocalSolPS) {
     SetMockTime(100);
-    MarkStartTime();
+    miningTimer.start();
 
     // No time has passed
     EXPECT_EQ(0, GetLocalSolPS());
@@ -27,4 +75,20 @@ TEST(Metrics, GetLocalSolPS) {
     solutionTargetChecks.increment();
     solutionTargetChecks.increment();
     EXPECT_EQ(1.5, GetLocalSolPS());
+
+    // Stop timing
+    miningTimer.stop();
+    EXPECT_EQ(1.5, GetLocalSolPS());
+
+    // Increment time
+    SetMockTime(103);
+    EXPECT_EQ(1.5, GetLocalSolPS());
+
+    // Start timing again
+    miningTimer.start();
+    EXPECT_EQ(1.5, GetLocalSolPS());
+
+    // Increment time
+    SetMockTime(104);
+    EXPECT_EQ(1, GetLocalSolPS());
 }

src/metrics.cpp

@@ -17,6 +17,45 @@
 #include <sys/ioctl.h>
 #include <unistd.h>
 
+void AtomicTimer::start()
+{
+    std::unique_lock<std::mutex> lock(mtx);
+    if (threads < 1) {
+        start_time = GetTime();
+    }
+    ++threads;
+}
+
+void AtomicTimer::stop()
+{
+    std::unique_lock<std::mutex> lock(mtx);
+    // Ignore excess calls to stop()
+    if (threads > 0) {
+        --threads;
+        if (threads < 1) {
+            int64_t time_span = GetTime() - start_time;
+            total_time += time_span;
+        }
+    }
+}
+
+bool AtomicTimer::running()
+{
+    std::unique_lock<std::mutex> lock(mtx);
+    return threads > 0;
+}
+
+double AtomicTimer::rate(const AtomicCounter& count)
+{
+    std::unique_lock<std::mutex> lock(mtx);
+    int64_t duration = total_time;
+    if (threads > 0) {
+        // Timer is running, so get the latest count
+        duration += GetTime() - start_time;
+    }
+    return duration > 0 ? (double)count.get() / duration : 0;
+}
+
 CCriticalSection cs_metrics;
 
 boost::synchronized_value<int64_t> nNodeStartTime;
@@ -25,6 +64,7 @@ AtomicCounter transactionsValidated;
 AtomicCounter ehSolverRuns;
 AtomicCounter solutionTargetChecks;
 AtomicCounter minedBlocks;
+AtomicTimer miningTimer;
 
 boost::synchronized_value<std::list<uint256>> trackedBlocks;
 
@@ -51,14 +91,9 @@ int64_t GetUptime()
     return GetTime() - *nNodeStartTime;
 }
 
-double GetLocalSolPS_INTERNAL(int64_t uptime)
-{
-    return uptime > 0 ? (double)solutionTargetChecks.get() / uptime : 0;
-}
-
 double GetLocalSolPS()
 {
-    return GetLocalSolPS_INTERNAL(GetUptime());
+    return miningTimer.rate(solutionTargetChecks);
 }
 
 void TriggerRefresh()
@@ -121,16 +156,32 @@ void ConnectMetricsScreen()
     uiInterface.InitMessage.connect(metrics_InitMessage);
 }
 
-int printNetworkStats()
+int printStats(bool mining)
 {
-    LOCK2(cs_main, cs_vNodes);
+    // Number of lines that are always displayed
+    int lines = 4;
 
-    std::cout << "           " << _("Block height") << " | " << chainActive.Height() << std::endl;
-    std::cout << "  " << _("Network solution rate") << " | " << GetNetworkHashPS(120, -1) << " Sol/s" << std::endl;
-    std::cout << "            " << _("Connections") << " | " << vNodes.size() << std::endl;
+    int height;
+    size_t connections;
+    int64_t netsolps;
+    {
+        LOCK2(cs_main, cs_vNodes);
+        height = chainActive.Height();
+        connections = vNodes.size();
+        netsolps = GetNetworkHashPS(120, -1);
+    }
+    auto localsolps = GetLocalSolPS();
+
+    std::cout << "           " << _("Block height") << " | " << height << std::endl;
+    std::cout << "            " << _("Connections") << " | " << connections << std::endl;
+    std::cout << "  " << _("Network solution rate") << " | " << netsolps << " Sol/s" << std::endl;
+    if (mining && miningTimer.running()) {
+        std::cout << "    " << _("Local solution rate") << " | " << strprintf("%.4f Sol/s", localsolps) << std::endl;
+        lines++;
+    }
     std::cout << std::endl;
 
-    return 4;
+    return lines;
 }
 
 int printMiningStatus(bool mining)
@@ -148,8 +199,23 @@ int printMiningStatus(bool mining)
             else
                 nThreads = boost::thread::hardware_concurrency();
         }
-        std::cout << strprintf(_("You are mining with the %s solver on %d threads."),
-                               GetArg("-equihashsolver", "default"), nThreads) << std::endl;
+        if (miningTimer.running()) {
+            std::cout << strprintf(_("You are mining with the %s solver on %d threads."),
+                                   GetArg("-equihashsolver", "default"), nThreads) << std::endl;
+        } else {
+            bool fvNodesEmpty;
+            {
+                LOCK(cs_vNodes);
+                fvNodesEmpty = vNodes.empty();
+            }
+            if (fvNodesEmpty) {
+                std::cout << _("Mining is paused while waiting for connections.") << std::endl;
+            } else if (IsInitialBlockDownload()) {
+                std::cout << _("Mining is paused while downloading blocks.") << std::endl;
+            } else {
+                std::cout << _("Mining is paused (a JoinSplit may be in progress).") << std::endl;
+            }
+        }
         lines++;
     } else {
         std::cout << _("You are currently not mining.") << std::endl;
@@ -201,11 +267,8 @@ int printMetrics(size_t cols, bool mining)
     }
 
     if (mining && loaded) {
-        double solps = GetLocalSolPS_INTERNAL(uptime);
-        std::string strSolps = strprintf("%.4f Sol/s", solps);
-        std::cout << "- " << strprintf(_("You have contributed %s on average to the network solution rate."), strSolps) << std::endl;
         std::cout << "- " << strprintf(_("You have completed %d Equihash solver runs."), ehSolverRuns.get()) << std::endl;
-        lines += 2;
+        lines++;
 
         int mined = 0;
         int orphaned = 0;
@@ -360,9 +423,9 @@ void ThreadShowMetricsScreen()
 #endif
 
         if (loaded) {
-            lines += printNetworkStats();
+            lines += printStats(mining);
+            lines += printMiningStatus(mining);
         }
-        lines += printMiningStatus(mining);
         lines += printMetrics(cols, mining);
         lines += printMessageBox(cols);
         lines += printInitMessage();

src/metrics.h

@@ -5,6 +5,7 @@
 #include "uint256.h"
 
 #include <atomic>
+#include <mutex>
 #include <string>
 
 struct AtomicCounter {
@@ -20,14 +21,41 @@ struct AtomicCounter {
         --value;
     }
 
-    int get(){
+    int get() const {
         return value.load();
     }
 };
 
+class AtomicTimer {
+private:
+    std::mutex mtx;
+    uint64_t threads;
+    int64_t start_time;
+    int64_t total_time;
+
+public:
+    AtomicTimer() : threads(0), start_time(0), total_time(0) {}
+
+    /**
+     * Starts timing on first call, and counts the number of calls.
+     */
+    void start();
+
+    /**
+     * Counts number of calls, and stops timing after it has been called as
+     * many times as start().
+     */
+    void stop();
+
+    bool running();
+
+    double rate(const AtomicCounter& count);
+};
+
 extern AtomicCounter transactionsValidated;
 extern AtomicCounter ehSolverRuns;
 extern AtomicCounter solutionTargetChecks;
+extern AtomicTimer miningTimer;
 
 void TrackMinedBlock(uint256 hash);
 

src/miner.cpp

@@ -528,12 +528,14 @@ void static BitcoinMiner()
             cancelSolver = true;
         }
     );
+    miningTimer.start();
 
     try {
         while (true) {
             if (chainparams.MiningRequiresPeers()) {
                 // Busy-wait for the network to come online so we don't waste time mining
                 // on an obsolete chain. In regtest mode we expect to fly solo.
+                miningTimer.stop();
                 do {
                     bool fvNodesEmpty;
                     {
@@ -544,6 +546,7 @@ void static BitcoinMiner()
                         break;
                     MilliSleep(1000);
                 } while (true);
+                miningTimer.start();
             }
 
             //
@@ -721,16 +724,19 @@ void static BitcoinMiner()
     }
     catch (const boost::thread_interrupted&)
     {
+        miningTimer.stop();
         c.disconnect();
         LogPrintf("ZcashMiner terminated\n");
         throw;
     }
     catch (const std::runtime_error &e)
     {
+        miningTimer.stop();
         c.disconnect();
         LogPrintf("ZcashMiner runtime error: %s\n", e.what());
         return;
     }
+    miningTimer.stop();
     c.disconnect();
 }