Daemon: Print estimates for time until fully synced

src/common/util.cpp

@@ -66,7 +66,6 @@ using namespace epee;
 #include "util.h"
 #include "stack_trace.h"
 #include "memwipe.h"
-#include "cryptonote_config.h"
 #include "net/http_client.h"                        // epee::net_utils::...
 #include "readline_buffer.h"
 
@@ -1074,16 +1073,33 @@ std::string get_nix_version_display_string()
   {
     if (seconds < 60)
       return std::to_string(seconds) + " seconds";
+    std::stringstream ss;
+    ss << std::fixed << std::setprecision(1);
     if (seconds < 3600)
-      return std::to_string((uint64_t)(seconds / 60)) + " minutes";
+    {
+      ss << seconds / 60.f;
+      return ss.str() + " minutes";
+    }
     if (seconds < 3600 * 24)
-      return std::to_string((uint64_t)(seconds / 3600)) + " hours";
-    if (seconds < 3600 * 24 * 30.5)
-      return std::to_string((uint64_t)(seconds / (3600 * 24))) + " days";
-    if (seconds < 3600 * 24 * 365.25)
-      return std::to_string((uint64_t)(seconds / (3600 * 24 * 30.5))) + " months";
-    if (seconds < 3600 * 24 * 365.25 * 100)
-      return std::to_string((uint64_t)(seconds / (3600 * 24 * 30.5 * 365.25))) + " years";
+    {
+      ss << seconds / 3600.f;
+      return ss.str() + " hours";
+    }
+    if (seconds < 3600 * 24 * 30.5f)
+    {
+      ss << seconds / (3600 * 24.f);
+      return ss.str() + " days";
+    }
+    if (seconds < 3600 * 24 * 365.25f)
+    {
+      ss << seconds / (3600 * 24 * 30.5f);
+      return ss.str() + " months";
+    }
+    if (seconds < 3600 * 24 * 365.25f * 100)
+    {
+      ss << seconds / (3600 * 24 * 365.25f);
+      return ss.str() + " years";
+    }
     return "a long time";
   }
 
@@ -1279,6 +1295,86 @@ std::string get_nix_version_display_string()
     return lines;
   }
 
+  // Calculate a "sync weight" over ranges of blocks in the blockchain, suitable for
+  // calculating sync time estimates
+  uint64_t cumulative_block_sync_weight(cryptonote::network_type nettype, uint64_t start_block, uint64_t num_blocks)
+  {
+    if (nettype != cryptonote::MAINNET)
+    {
+      // No detailed data available except for Mainnet: Give back the number of blocks
+      // as a very simple and non-varying block sync weight for ranges of Testnet and
+      // Stagenet blocks
+      return num_blocks;
+    }
+
+    // The following is a table of average blocks sizes in bytes over the Monero mainnet
+    // blockchain, where the block size is averaged over ranges of 10,000 blocks
+    // (about 2 weeks worth of blocks each).
+    // The first array entry of 442 thus means "The average byte size of the blocks
+    // 0 .. 9,999 is 442". The info "block_size" from the "get_block_header_by_height"
+    // RPC call was used for calculating this. This table (and the whole mechanism
+    // of calculating a "sync weight") is most important when estimating times for
+    // syncing from scratch. Without it the fast progress through the (in comparison)
+    // rather small blocks in the early blockchain) would lead to vastly underestimated
+    // total sync times.
+    // It's no big problem for estimates that this table will, over time, and if not
+    // updated, miss larger and larger parts at the top of the blockchain, as long
+    // as block size averages there do not differ wildly.
+    // Without time-consuming tests it's hard to say how much the estimates would
+    // improve if one would not only take block sizes into account, but also varying
+    // verification times i.e. the different CPU effort needed for the different
+    // transaction types (pre / post RingCT, pre / post Bulletproofs).
+    // Testnet and Stagenet are neglected here because of their much smaller
+    // importance.
+    static const uint32_t average_block_sizes[] =
+    {
+      442, 1211, 1445, 1763, 2272, 8217, 5603, 9999, 16358, 10805, 5290, 4362,
+      4325, 5584, 4515, 5008, 4789, 5196, 7660, 3829, 6034, 2925, 3762, 2545,
+      2437, 2553, 2167, 2761, 2015, 1969, 2350, 1731, 2367, 2078, 2026, 3518,
+      2214, 1908, 1780, 1640, 1976, 1647, 1921, 1716, 1895, 2150, 2419, 2451,
+      2147, 2327, 2251, 1644, 1750, 1481, 1570, 1524, 1562, 1668, 1386, 1494,
+      1637, 1880, 1431, 1472, 1637, 1363, 1762, 1597, 1999, 1564, 1341, 1388,
+      1530, 1476, 1617, 1488, 1368, 1906, 1403, 1695, 1535, 1598, 1318, 1234,
+      1358, 1406, 1698, 1554, 1591, 1758, 1426, 2389, 1946, 1533, 1308, 2701,
+      1525, 1653, 3580, 1889, 2913, 8164, 5154, 3762, 3356, 4360, 3589, 4844,
+      4232, 3781, 3882, 5924, 10790, 7185, 7442, 8214, 8509, 7484, 6939, 7391,
+      8210, 15572, 39680, 44810, 53873, 54639, 68227, 63428, 62386, 68504,
+      83073, 103858, 117573, 98089, 96793, 102337, 94714, 129568, 251584,
+      132026, 94579, 94516, 95722, 106495, 121824, 153983, 162338, 136608,
+      137104, 109872, 91114, 84757, 96339, 74251, 94314, 143216, 155837,
+      129968, 120201, 109913, 101588, 97332, 104611, 95310, 93419, 113345,
+      100743, 92152, 57565, 22533, 37564, 21823, 19980, 18277, 18402, 14344,
+      12142, 15842, 13677, 17631, 18294, 22270, 41422, 39296, 36688, 33512,
+      33831, 27582, 22276, 27516, 27317, 25505, 24426, 20566, 23045, 26766,
+      28185, 26169, 27011,
+      28642    // Blocks 1,990,000 to 1,999,999 in December 2019
+    };
+    const uint64_t block_range_size = 10000;
+
+    uint64_t num_block_sizes = sizeof(average_block_sizes) / sizeof(average_block_sizes[0]);
+    uint64_t weight = 0;
+    uint64_t table_index = start_block / block_range_size;
+    for (;;) {
+      if (num_blocks == 0)
+      {
+        break;
+      }
+      if (table_index >= num_block_sizes)
+      {
+        // Take all blocks beyond our table as having the size of the blocks
+        // in the last table entry i.e. in the most recent known block range
+        weight += num_blocks * average_block_sizes[num_block_sizes - 1];
+        break;
+      }
+      uint64_t portion_size = std::min(num_blocks, block_range_size - start_block % block_range_size);
+      weight += portion_size * average_block_sizes[table_index];
+      table_index++;
+      num_blocks -= portion_size;
+      start_block += portion_size;
+    }
+    return weight;
+  }
+
   std::vector<std::pair<std::string, size_t>> split_string_by_width(const std::string &s, size_t columns)
   {
     std::vector<std::string> lines;

src/common/util.h

@@ -46,6 +46,7 @@
 #endif
 
 #include "crypto/hash.h"
+#include "cryptonote_config.h"
 
 /*! \brief Various Tools
  *
@@ -252,4 +253,6 @@ namespace tools
   void clear_screen();
 
   std::vector<std::pair<std::string, size_t>> split_string_by_width(const std::string &s, size_t columns);
+
+  uint64_t cumulative_block_sync_weight(cryptonote::network_type nettype, uint64_t start_block, uint64_t num_blocks);
 }

src/cryptonote_protocol/cryptonote_protocol_handler.h

@@ -169,6 +169,14 @@ namespace cryptonote
     size_t m_block_download_max_size;
     bool m_sync_pruned_blocks;
 
+    // Values for sync time estimates
+    boost::posix_time::ptime m_sync_start_time;
+    boost::posix_time::ptime m_period_start_time;
+    uint64_t m_sync_start_height;
+    uint64_t m_period_start_height;
+    uint64_t get_estimated_remaining_sync_seconds(uint64_t current_blockchain_height, uint64_t target_blockchain_height);
+    std::string get_periodic_sync_estimate(uint64_t current_blockchain_height, uint64_t target_blockchain_height);
+
     boost::mutex m_buffer_mutex;
     double get_avg_block_size();
     boost::circular_buffer<size_t> m_avg_buffer = boost::circular_buffer<size_t>(10);

src/cryptonote_protocol/cryptonote_protocol_handler.inl

@@ -43,6 +43,7 @@
 #include "profile_tools.h"
 #include "net/network_throttle-detail.hpp"
 #include "common/pruning.h"
+#include "common/util.h"
 
 #undef MONERO_DEFAULT_LOG_CATEGORY
 #define MONERO_DEFAULT_LOG_CATEGORY "net.cn"
@@ -367,7 +368,7 @@ namespace cryptonote
     uint64_t last_block_v1 = m_core.get_nettype() == TESTNET ? 624633 : m_core.get_nettype() == MAINNET ? 1009826 : (uint64_t)-1;
     uint64_t diff_v2 = max_block_height > last_block_v1 ? std::min(abs_diff, max_block_height - last_block_v1) : 0;
     MCLOG(is_inital ? el::Level::Info : el::Level::Debug, "global", el::Color::Yellow, context <<  "Sync data returned a new top block candidate: " << m_core.get_current_blockchain_height() << " -> " << hshd.current_height
-      << " [Your node is " << abs_diff << " blocks (" << ((abs_diff - diff_v2) / (24 * 60 * 60 / DIFFICULTY_TARGET_V1)) + (diff_v2 / (24 * 60 * 60 / DIFFICULTY_TARGET_V2)) << " days) "
+      << " [Your node is " << abs_diff << " blocks (" << tools::get_human_readable_timespan((abs_diff - diff_v2) * DIFFICULTY_TARGET_V1 + diff_v2 * DIFFICULTY_TARGET_V2) << ") "
       << (0 <= diff ? std::string("behind") : std::string("ahead"))
       << "] " << ENDL << "SYNCHRONIZATION started");
       if (hshd.current_height >= m_core.get_current_blockchain_height() + 5) // don't switch to unsafe mode just for a few blocks
@@ -1158,6 +1159,55 @@ namespace cryptonote
     return 1;
   }
 
+  // Get an estimate for the remaining sync time from given current to target blockchain height, in seconds
+  template<class t_core>
+  uint64_t t_cryptonote_protocol_handler<t_core>::get_estimated_remaining_sync_seconds(uint64_t current_blockchain_height, uint64_t target_blockchain_height)
+  {
+    // The average sync speed varies so much, even averaged over quite long time periods like 10 minutes,
+    // that using some sliding window would be difficult to implement without often leading to bad estimates.
+    // The simplest strategy - always average sync speed over the maximum available interval i.e. since sync
+    // started at all (from "m_sync_start_time" and "m_sync_start_height") - gives already useful results
+    // and seems to be quite robust. Some quite special cases like "Internet connection suddenly becoming
+    // much faster after syncing already a long time, and staying fast" are not well supported however.
+
+    if (target_blockchain_height <= current_blockchain_height)
+    {
+      // Syncing stuck, or other special circumstance: Avoid errors, simply give back 0
+      return 0;
+    }
+
+    const boost::posix_time::ptime now = boost::posix_time::microsec_clock::universal_time();
+    const boost::posix_time::time_duration sync_time = now - m_sync_start_time;
+    cryptonote::network_type nettype = m_core.get_nettype();
+
+    // Don't simply use remaining number of blocks for the estimate but "sync weight" as provided by
+    // "cumulative_block_sync_weight" which knows about strongly varying Monero mainnet block sizes
+    uint64_t synced_weight = tools::cumulative_block_sync_weight(nettype, m_sync_start_height, current_blockchain_height - m_sync_start_height);
+    float us_per_weight = (float)sync_time.total_microseconds() / (float)synced_weight;
+    uint64_t remaining_weight = tools::cumulative_block_sync_weight(nettype, current_blockchain_height, target_blockchain_height - current_blockchain_height);
+    float remaining_us = us_per_weight * (float)remaining_weight;
+    return (uint64_t)(remaining_us / 1e6);
+  }
+
+  // Return a textual remaining sync time estimate, or the empty string if waiting period not yet over
+  template<class t_core>
+  std::string t_cryptonote_protocol_handler<t_core>::get_periodic_sync_estimate(uint64_t current_blockchain_height, uint64_t target_blockchain_height)
+  {
+    std::string text = "";
+    const boost::posix_time::ptime now = boost::posix_time::microsec_clock::universal_time();
+    boost::posix_time::time_duration period_sync_time = now - m_period_start_time;
+    if (period_sync_time > boost::posix_time::minutes(2))
+    {
+      // Period is over, time to report another estimate
+      uint64_t remaining_seconds = get_estimated_remaining_sync_seconds(current_blockchain_height, target_blockchain_height);
+      text = tools::get_human_readable_timespan(remaining_seconds);
+
+      // Start the new period
+      m_period_start_time = now;
+    }
+    return text;
+  }
+
   template<class t_core>
   int t_cryptonote_protocol_handler<t_core>::try_add_next_blocks(cryptonote_connection_context& context)
   {
@@ -1186,6 +1236,9 @@ namespace cryptonote
           if (!starting)
             m_last_add_end_time = tools::get_tick_count();
         });
+        m_sync_start_time = boost::posix_time::microsec_clock::universal_time();
+        m_sync_start_height = m_core.get_current_blockchain_height();
+        m_period_start_time = m_sync_start_time;
 
         while (1)
         {
@@ -1436,7 +1489,16 @@ namespace cryptonote
               if (completion_percent == 100) // never show 100% if not actually up to date
                 completion_percent = 99;
               progress_message = " (" + std::to_string(completion_percent) + "%, "
-                  + std::to_string(target_blockchain_height - current_blockchain_height) + " left)";
+                  + std::to_string(target_blockchain_height - current_blockchain_height) + " left";
+              std::string time_message = get_periodic_sync_estimate(current_blockchain_height, target_blockchain_height);
+              if (!time_message.empty())
+              {
+                uint64_t total_blocks_to_sync = target_blockchain_height - m_sync_start_height;
+                uint64_t total_blocks_synced = current_blockchain_height - m_sync_start_height;
+                progress_message += ", " + std::to_string(total_blocks_synced * 100 / total_blocks_to_sync) + "% of total synced";
+                progress_message += ", estimated " + time_message + " left";
+              }
+              progress_message += ")";
             }
             const uint32_t previous_stripe = tools::get_pruning_stripe(previous_height, target_blockchain_height, CRYPTONOTE_PRUNING_LOG_STRIPES);
             const uint32_t current_stripe = tools::get_pruning_stripe(current_blockchain_height, target_blockchain_height, CRYPTONOTE_PRUNING_LOG_STRIPES);
@@ -2174,8 +2236,26 @@ skip:
   bool t_cryptonote_protocol_handler<t_core>::on_connection_synchronized()
   {
     bool val_expected = false;
-    if(!m_core.is_within_compiled_block_hash_area(m_core.get_current_blockchain_height()) && m_synchronized.compare_exchange_strong(val_expected, true))
+    uint64_t current_blockchain_height = m_core.get_current_blockchain_height();
+    if(!m_core.is_within_compiled_block_hash_area(current_blockchain_height) && m_synchronized.compare_exchange_strong(val_expected, true))
     {
+      if ((current_blockchain_height > m_sync_start_height) && (m_sync_spans_downloaded > 0))
+      {
+        uint64_t synced_blocks = current_blockchain_height - m_sync_start_height;
+        // Report only after syncing an "interesting" number of blocks:
+        if (synced_blocks > 20)
+        {
+          const boost::posix_time::ptime now = boost::posix_time::microsec_clock::universal_time();
+          uint64_t synced_seconds = (now - m_sync_start_time).total_seconds();
+          if (synced_seconds == 0)
+          {
+            synced_seconds = 1;
+          }
+          float blocks_per_second = (1000 * synced_blocks / synced_seconds) / 1000.0f;
+          MGINFO_YELLOW("Synced " << synced_blocks << " blocks in "
+            << tools::get_human_readable_timespan(synced_seconds) << " (" << blocks_per_second << " blocks per second)");
+        }
+      }
       MGINFO_YELLOW(ENDL << "**********************************************************************" << ENDL
         << "You are now synchronized with the network. You may now start monero-wallet-cli." << ENDL
         << ENDL