Optimized Logger class to do less redundant copying

Summary
---

When reviewing !834 I noticed the Logger class does a lot of extra
copying and other assorted inefficient operations.

Summary of fixes:

- Made the real workhorse function, `LogPrintStr` do less copying and also
  accept an rvalue reference (`&&`) as a parameter as an optimization.
- `LogPrintStr` is currently only called in 1 place, from an inline
  function in the header which builds a temporary string.  We `std::move`
  that temporary string when calling `LogPrintStr` to save on 1 copy there.
- The `LogTimestampStr` function was inefficeint and wasn't leveraging RVO
  and other things.  It has been modified and renamed to
  `PrependTimestampStr` and it now operates on the string it is passed
  in-place as an in/out parameter for efficienty. This function is private
  and only called in 1 place, so the "API change" is ok here.
- Other assorted cleanup.

Test Plan
---

- `ninja check check-functional`
- Also try building with `cmake -GNinja .. -DCMAKE_BUILD_TYPE=Debug`
- Try running bitcoind with `-logthreadnames=1 -logtimemicros
  -debug=all` (and/or combinations thereof)

The debug.log file and the console output should still look ok.

src/logging.cpp

@@ -147,56 +147,62 @@ BCLog::Logger::~Logger() {
     }
 }
 
-std::string BCLog::Logger::LogTimestampStr(const std::string &str) {
-    std::string strStamped;
-
-    if (!m_log_timestamps) {
-        return str;
+void BCLog::Logger::PrependTimestampStr(std::string &str) {
+    if (!m_log_timestamps || !m_started_new_line)
+        return;
+
+    const int64_t nTimeMicros = GetTimeMicros();
+    std::string tmpStr = FormatISO8601DateTime(nTimeMicros / 1000000);
+    if (m_log_time_micros) {
+        tmpStr.pop_back(); // pop off the trailing Z
+        tmpStr += strprintf(".%06dZ", nTimeMicros % 1000000);
     }
-
-    if (m_started_new_line) {
-        int64_t nTimeMicros = GetTimeMicros();
-        strStamped = FormatISO8601DateTime(nTimeMicros / 1000000);
-        if (m_log_time_micros) {
-            strStamped.pop_back();
-            strStamped += strprintf(".%06dZ", nTimeMicros % 1000000);
-        }
-        int64_t mocktime = GetMockTime();
-        if (mocktime) {
-            strStamped +=
-                " (mocktime: " + FormatISO8601DateTime(mocktime) + ")";
-        }
-        strStamped += ' ' + str;
-    } else {
-        strStamped = str;
+    const int64_t mocktime = GetMockTime();
+    if (mocktime) {
+        tmpStr +=
+            " (mocktime: " + FormatISO8601DateTime(mocktime) + ")";
     }
-
-    return strStamped;
+    // reserve space in tmp buffer for appending: ' ' + str
+    tmpStr.reserve(tmpStr.size() + 1 + str.size());
+    tmpStr += ' ';
+    tmpStr += str; // finally, add the log line after having prepended the timestamp
+    str = std::move(tmpStr);  // move line buffer back onto out value
 }
 
-void BCLog::Logger::LogPrintStr(const std::string &str)
+void BCLog::Logger::LogPrintStr(std::string &&str)
 {
-    std::string str_prefixed = str;
+    if (!m_print_to_console && !m_print_to_file)
+        return; // Nothing to do!
 
     if (m_log_threadnames && m_started_new_line) {
-        str_prefixed.insert(0, "[" + util::ThreadGetInternalName() + "] ");
+        // below does: str = "[" + threadName + "] " + str; (but with less copying)
+        std::string tmp;
+        const auto &threadName = util::ThreadGetInternalName();
+        tmp.reserve(str.size() + threadName.size() + 3); // reserve space
+        tmp += '[';
+        tmp += threadName;
+        tmp += "] ";
+        tmp += str;
+        str = std::move(tmp); // move tmp back onto str for efficiency
     }
 
-    str_prefixed = LogTimestampStr(str_prefixed);
+    const bool hadNL = !str.empty() && str.back() == '\n';
+
+    PrependTimestampStr(str);
 
-    m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
+    m_started_new_line = hadNL;
 
     if (m_print_to_console) {
         // print to console
-        fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
+        FileWriteStr(str, stdout);
         fflush(stdout);
     }
     if (m_print_to_file) {
         std::lock_guard<std::mutex> scoped_lock(m_file_mutex);
 
         // Buffer if we haven't opened the log yet.
         if (m_fileout == nullptr) {
-            m_msgs_before_open.push_back(str_prefixed);
+            m_msgs_before_open.emplace_back(std::move(str));
         } else {
             // Reopen the log file, if requested.
             if (m_reopen_file) {
@@ -209,7 +215,7 @@ void BCLog::Logger::LogPrintStr(const std::string &str)
                     m_fileout = new_fileout;
                 }
             }
-            FileWriteStr(str_prefixed, m_fileout);
+            FileWriteStr(str, m_fileout);
         }
     }
 }

src/logging.h

@@ -15,6 +15,7 @@
 #include <list>
 #include <mutex>
 #include <string>
+#include <utility>
 
 static const bool DEFAULT_LOGTIMEMICROS = false;
 static const bool DEFAULT_LOGIPS = false;
@@ -76,7 +77,7 @@ class Logger {
      */
     std::atomic<uint32_t> m_categories{0};
 
-    std::string LogTimestampStr(const std::string &str);
+    void PrependTimestampStr(std::string &str);
 
 public:
     bool m_print_to_console = false;
@@ -92,7 +93,8 @@ class Logger {
     ~Logger();
 
     /** Send a string to the log output */
-    void LogPrintStr(const std::string &str);
+    void LogPrintStr(std::string &&str);
+    void LogPrintStr(const std::string &str) { LogPrintStr(std::string{str}); }
 
     /** Returns whether logs will be written to any output */
     bool Enabled() const { return m_print_to_console || m_print_to_file; }
@@ -148,7 +150,7 @@ static inline void LogPrintf(const char *fmt, const Args &... args) {
             log_msg = "Error \"" + std::string(fmterr.what()) +
                       "\" while formatting log message: " + fmt;
         }
-        LogInstance().LogPrintStr(log_msg);
+        LogInstance().LogPrintStr(std::move(log_msg));
     }
 }