Application of TheBlueMatt's original async logging patch

jamesob · jamesob · commit 7ab904ad933a · 2018-05-14T11:37:19.000-04:00
bitcoinfibre@6b6a3ae
diff --git a/src/init.cpp b/src/init.cpp
@@ -290,6 +290,7 @@ void Shutdown()
     g_wallet_init_interface.Close();
     globalVerifyHandle.reset();
     ECC_Stop();
+    StopDebugLogFlushThread();
     LogPrintf("%s: done\n", __func__);
 }
 
diff --git a/src/logging.cpp b/src/logging.cpp
@@ -5,6 +5,9 @@
 
 #include <logging.h>
 #include <utiltime.h>
+#include <mutex>
+#include <condition_variable>
+#include <thread>
 
 const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
 
@@ -25,9 +28,75 @@ BCLog::Logger* const g_logger = new BCLog::Logger();
 
 bool fLogIPs = DEFAULT_LOGIPS;
 
+#define LOG_LINE_BUFFER_SIZE 128
+static std::atomic_int g_next_pending_log_line(0);
+static std::atomic_int g_next_undef_log_line(0);
+static std::atomic_bool g_debug_log_flush_thread_exit;
+static std::mutex g_log_buff_mutex;
+static std::condition_variable g_log_buff_cv;
+static std::array<std::string, LOG_LINE_BUFFER_SIZE> g_debug_log_buff;
+static std::unique_ptr<std::thread> g_buff_flush_thread; // non-ptr fails to build in LTO?
+static std::once_flag g_buff_flush_thread_started;
+
+static void DebugLogFlush()
+{
+    while (true) {
+        int next_pending_log = g_next_pending_log_line.load(std::memory_order_acquire);
+        int next_undef_log = g_next_undef_log_line.load(std::memory_order_acquire);
+        if (next_pending_log == next_undef_log) {
+            if (g_debug_log_flush_thread_exit) return;
+            std::unique_lock<std::mutex> lock(g_log_buff_mutex);
+            while (next_pending_log == next_undef_log && !g_debug_log_flush_thread_exit) {
+                g_log_buff_cv.wait(lock);
+                next_pending_log = g_next_pending_log_line.load(std::memory_order_acquire);
+                next_undef_log = g_next_undef_log_line.load(std::memory_order_acquire);
+            }
+        }
+
+        while (next_pending_log != next_undef_log) {
+            fwrite(g_debug_log_buff[next_pending_log].data(), 1, g_debug_log_buff[next_pending_log].size(), g_logger->m_fileout);
+            g_debug_log_buff[next_pending_log].clear();
+            g_debug_log_buff[next_pending_log].shrink_to_fit();
+            next_pending_log = (next_pending_log + 1) % LOG_LINE_BUFFER_SIZE;
+            g_next_pending_log_line.store(next_pending_log, std::memory_order_release);
+            g_log_buff_cv.notify_one();
+        }
+    }
+}
+
+void StopDebugLogFlushThread() {
+    g_debug_log_flush_thread_exit = true;
+    {
+        std::unique_lock<std::mutex> lock(g_log_buff_mutex);
+        g_log_buff_cv.notify_all();
+    }
+    if (g_buff_flush_thread) {
+        g_buff_flush_thread->join();
+    }
+}
+
 static int FileWriteStr(const std::string &str, FILE *fp)
 {
-    return fwrite(str.data(), 1, str.size(), fp);
+    std::call_once(g_buff_flush_thread_started, [] {
+        g_buff_flush_thread.reset(new std::thread(DebugLogFlush));
+        });
+
+    std::unique_lock<std::mutex> lock(g_log_buff_mutex);
+    int next_pending_log = g_next_pending_log_line.load(std::memory_order_acquire);
+    int next_undef_log = g_next_undef_log_line.load(std::memory_order_acquire);
+    while (next_pending_log == (next_undef_log + 1) % LOG_LINE_BUFFER_SIZE && !g_debug_log_flush_thread_exit) {
+        g_log_buff_cv.wait(lock);
+        next_pending_log = g_next_pending_log_line.load(std::memory_order_acquire);
+        next_undef_log = g_next_undef_log_line.load(std::memory_order_acquire);
+    }
+    if (g_debug_log_flush_thread_exit) {
+        return fwrite(str.data(), 1, str.size(), fp);
+    } else {
+        g_debug_log_buff[next_undef_log] = str;
+        g_next_undef_log_line.store((next_undef_log + 1) % LOG_LINE_BUFFER_SIZE, std::memory_order_release);
+        g_log_buff_cv.notify_all();
+        return str.size();
+    }
 }
 
 bool BCLog::Logger::OpenDebugLog()
@@ -198,6 +267,7 @@ std::string BCLog::Logger::LogTimestampStr(const std::string &str)
     return strStamped;
 }
 
+
 void BCLog::Logger::LogPrintStr(const std::string &str)
 {
     std::string strTimestamped = LogTimestampStr(str);
diff --git a/src/logging.h b/src/logging.h
@@ -59,7 +59,6 @@ namespace BCLog {
     class Logger
     {
     private:
-        FILE* m_fileout = nullptr;
         std::mutex m_file_mutex;
         std::list<std::string> m_msgs_before_open;
 
@@ -76,6 +75,7 @@ namespace BCLog {
         std::string LogTimestampStr(const std::string& str);
 
     public:
+        FILE* m_fileout = nullptr;
         bool m_print_to_console = false;
         bool m_print_to_file = false;
 
@@ -163,4 +163,6 @@ template<typename T, typename... Args> static inline void MarkUsed(const T& t, c
 } while(0)
 #endif
 
+void StopDebugLogFlushThread();
+
 #endif // BITCOIN_LOGGING_H

Original file line number	Diff line number	Diff line change
`@@ -290,6 +290,7 @@ void Shutdown()`
`290`	`290`	`g_wallet_init_interface.Close();`
`291`	`291`	`globalVerifyHandle.reset();`
`292`	`292`	`ECC_Stop();`
	`293`	`+ StopDebugLogFlushThread();`
`293`	`294`	`LogPrintf("%s: done\n", __func__);`
`294`	`295`	`}`
`295`	`296`