Merge #15849: Thread names in logs and deadlock debug tools

8722e54e56 threads: add thread names to deadlock debugging message (James O'Beirne)
383b186c28 threads: prefix log messages with thread names (James O'Beirne)
ddd95ccb80 tests: add threadutil tests (James O'Beirne)
ae5f2b6a6c threads: introduce util/threadnames, refactor thread naming (James O'Beirne)
188ca75e5f disable HAVE_THREAD_LOCAL on unreliable platforms (James O'Beirne)

Pull request description:

  I'm resurrecting this one (from #13168) because I need it to make progress on #15735.

  It's now off by default and can be turned on with `-logthreadnames=1`.

  Ran some benchmarks (IBD from local peer from 500_000 -> 504_000) and it's within spitting distance either on or off:

  ### threadnames off (default)

  #### 2018-05-threadnames.3 vs. master (absolute)
  |                      name                      | iterations |   2018-05-threadnames.3    |           master           |
  |------------------------------------------------|-----------:|----------------------------|----------------------------|
  | ibd.local.500000.504000.dbcache=2048           |          3 | 376.1584 (± 9.2944)        | 392.3414 (± 13.4238)       |
  | ibd.local.500000.504000.dbcache=2048.mem-usage |          3 | 2236117.3333 (± 1845.9623) | 2238690.6667 (± 2669.3487) |

  #### 2018-05-threadnames.3 vs. master (relative)
  |                      name                      | iterations | 2018-05-threadnames.3 | master |
  |------------------------------------------------|-----------:|----------------------:|-------:|
  | ibd.local.500000.504000.dbcache=2048           |          3 |                     1 |  1.043 |
  | ibd.local.500000.504000.dbcache=2048.mem-usage |          3 |                     1 |  1.001 |

  ### threadnames on

  #### 2018-05-threadnames-take-2 vs. master (absolute)
  |                      name                      | iterations | 2018-05-threadnames-take-2 |           master           |
  |------------------------------------------------|-----------:|----------------------------|----------------------------|
  | ibd.local.500000.504000.dbcache=2048           |          3 | 367.6861 (± 0.3941)        | 364.1667 (± 0.9776)        |
  | ibd.local.500000.504000.dbcache=2048.mem-usage |          3 | 2238461.3333 (± 3697.8730) | 2237014.6667 (± 3307.6966) |

  #### 2018-05-threadnames-take-2 vs. master (relative)
  |                      name                      | iterations | 2018-05-threadnames-take-2 | master |
  |------------------------------------------------|-----------:|---------------------------:|-------:|
  | ibd.local.500000.504000.dbcache=2048           |          3 |                      1.010 |   1.00 |
  | ibd.local.500000.504000.dbcache=2048.mem-usage |          3 |                      1.001 |   1.00 |
  ```

ACKs for commit 8722e5:
  Empact:
    utACK https://github.com/bitcoin/bitcoin/pull/15849/commits/8722e54e56fd959fd4ff2321b36a7640dee440c5
  jnewbery:
    utACK 8722e54e56fd959fd4ff2321b36a7640dee440c5
  MarcoFalke:
    re-utACK 8722e54e56fd959fd4ff2321b36a7640dee440c5 (Only change since my previous review is DEFAULT_LOGTHREADNAMES=false and stylistic updates

Tree-SHA512: 50af992708295b8d680cf10025262dd964e599a356bdfc1dfc84fb18c00afabcb34d3d12d551b0677ff81f8fccad0e17c1d5b24dfecb953a913bc77fdd1a4577

1 files changed, 16 insertions, 10 deletions

diff --git a/src/logging.cpp b/src/logging.cpp
index 36cad6573a..3eda4995db 100644
--- a/src/logging.cpp
+++ b/src/logging.cpp
@@ -4,8 +4,11 @@
 // file COPYING or http://www.opensource.org/licenses/mit-license.php.
 
 #include <logging.h>
+#include <util/threadnames.h>
 #include <util/time.h>
 
+#include <mutex>
+
 const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
 
 BCLog::Logger& LogInstance()
@@ -174,7 +177,7 @@ std::vector<CLogCategoryActive> ListActiveLogCategories()
     return ret;
 }
 
-std::string BCLog::Logger::LogTimestampStr(const std::string &str)
+std::string BCLog::Logger::LogTimestampStr(const std::string& str)
 {
     std::string strStamped;
 
@@ -196,21 +199,24 @@ std::string BCLog::Logger::LogTimestampStr(const std::string &str)
     } else
         strStamped = str;
 
-    if (!str.empty() && str[str.size()-1] == '\n')
-        m_started_new_line = true;
-    else
-        m_started_new_line = false;
-
     return strStamped;
 }
 
 void BCLog::Logger::LogPrintStr(const std::string &str)
 {
-    std::string strTimestamped = LogTimestampStr(str);
+    std::string str_prefixed = str;
+
+    if (m_log_threadnames && m_started_new_line) {
+        str_prefixed.insert(0, "[" + util::ThreadGetInternalName() + "] ");
+    }
+
+    str_prefixed = LogTimestampStr(str_prefixed);
+
+    m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
 
     if (m_print_to_console) {
         // print to console
-        fwrite(strTimestamped.data(), 1, strTimestamped.size(), stdout);
+        fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
         fflush(stdout);
     }
     if (m_print_to_file) {
@@ -218,7 +224,7 @@ void BCLog::Logger::LogPrintStr(const std::string &str)
 
         // buffer if we haven't opened the log yet
         if (m_fileout == nullptr) {
-            m_msgs_before_open.push_back(strTimestamped);
+            m_msgs_before_open.push_back(str_prefixed);
         }
         else
         {
@@ -232,7 +238,7 @@ void BCLog::Logger::LogPrintStr(const std::string &str)
                     m_fileout = new_fileout;
                 }
             }
-            FileWriteStr(strTimestamped, m_fileout);
+            FileWriteStr(str_prefixed, m_fileout);
         }
     }
 }