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

8722e54 threads: add thread names to deadlock debugging message (James O'Beirne)
383b186 threads: prefix log messages with thread names (James O'Beirne)
ddd95cc tests: add threadutil tests (James O'Beirne)
ae5f2b6 threads: introduce util/threadnames, refactor thread naming (James O'Beirne)
188ca75 disable HAVE_THREAD_LOCAL on unreliable platforms (James O'Beirne)

Pull request description:

  I'm resurrecting this one (from bitcoin#13168) because I need it to make progress on bitcoin#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 bitcoin@8722e54
  jnewbery:
    utACK 8722e54
  MarcoFalke:
    re-utACK 8722e54 (Only change since my previous review is DEFAULT_LOGTHREADNAMES=false and stylistic updates

Tree-SHA512: 50af992708295b8d680cf10025262dd964e599a356bdfc1dfc84fb18c00afabcb34d3d12d551b0677ff81f8fccad0e17c1d5b24dfecb953a913bc77fdd1a4577

Author: MarcoFalke

configure.ac

@@ -836,8 +836,23 @@ AC_LINK_IFELSE([AC_LANG_SOURCE([
   }
   ])],
   [
-    AC_DEFINE(HAVE_THREAD_LOCAL,1,[Define if thread_local is supported.])
-    AC_MSG_RESULT(yes)
+   case $host in
+     *mingw*)
+        # mingw32's implementation of thread_local has also been shown to behave
+        # erroneously under concurrent usage; see:
+        # https://gist.github.com/jamesob/fe9a872051a88b2025b1aa37bfa98605
+        AC_MSG_RESULT(no)
+        ;;
+      *darwin*)
+        # TODO enable thread_local on later versions of Darwin where it is
+        # supported (per https://stackoverflow.com/a/29929949)
+        AC_MSG_RESULT(no)
+        ;;
+      *)
+        AC_DEFINE(HAVE_THREAD_LOCAL,1,[Define if thread_local is supported.])
+        AC_MSG_RESULT(yes)
+        ;;
+    esac
   ],
   [
     AC_MSG_RESULT(no)

doc/release-notes-15849.md

@@ -0,0 +1,6 @@
+Thread names in logs
+--------------------
+
+On platforms supporting `thread_local`, log lines can be prefixed with the name
+of the thread that caused the log. To enable this behavior, use
+`-logthreadnames=1`.

src/Makefile.am

@@ -209,6 +209,7 @@ BITCOIN_CORE_H = \
   util/memory.h \
   util/moneystr.h \
   util/rbf.h \
+  util/threadnames.h \
   util/time.h \
   util/url.h \
   util/validation.h \
@@ -489,6 +490,7 @@ libbitcoin_util_a_SOURCES = \
   util/system.cpp \
   util/moneystr.cpp \
   util/rbf.cpp \
+  util/threadnames.cpp \
   util/strencodings.cpp \
   util/time.cpp \
   util/url.cpp \

src/Makefile.test.include

@@ -138,6 +138,7 @@ BITCOIN_TESTS =\
   test/skiplist_tests.cpp \
   test/streams_tests.cpp \
   test/sync_tests.cpp \
+  test/util_threadnames_tests.cpp \
   test/timedata_tests.cpp \
   test/torcontrol_tests.cpp \
   test/transaction_tests.cpp \

src/bitcoind.cpp

@@ -19,6 +19,7 @@
 #include <util/system.h>
 #include <httpserver.h>
 #include <httprpc.h>
+#include <util/threadnames.h>
 #include <util/strencodings.h>
 #include <walletinitinterface.h>
 
@@ -64,6 +65,8 @@ static bool AppInit(int argc, char* argv[])
 
     bool fRet = false;
 
+    util::ThreadRename("init");
+
     //
     // Parameters
     //

src/httpserver.cpp

@@ -6,6 +6,7 @@
 
 #include <chainparamsbase.h>
 #include <compat.h>
+#include <util/threadnames.h>
 #include <util/system.h>
 #include <util/strencodings.h>
 #include <netbase.h>
@@ -17,7 +18,7 @@
 #include <memory>
 #include <stdio.h>
 #include <stdlib.h>
-#include <string.h>
+#include <string>
 
 #include <sys/types.h>
 #include <sys/stat.h>
@@ -284,7 +285,7 @@ static void http_reject_request_cb(struct evhttp_request* req, void*)
 /** Event dispatcher thread */
 static bool ThreadHTTP(struct event_base* base)
 {
-    RenameThread("bitcoin-http");
+    util::ThreadRename("http");
     LogPrint(BCLog::HTTP, "Entering http event loop\n");
     event_base_dispatch(base);
     // Event loop will be interrupted by InterruptHTTPServer()
@@ -335,9 +336,9 @@ static bool HTTPBindAddresses(struct evhttp* http)
 }
 
 /** Simple wrapper to set thread name and run work queue */
-static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue)
+static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue, int worker_num)
 {
-    RenameThread("bitcoin-httpworker");
+    util::ThreadRename(strprintf("httpworker.%i", worker_num));
     queue->Run();
 }
 
@@ -430,7 +431,7 @@ void StartHTTPServer()
     threadHTTP = std::thread(ThreadHTTP, eventBase);
 
     for (int i = 0; i < rpcThreads; i++) {
-        g_thread_http_workers.emplace_back(HTTPWorkQueueRun, workQueue);
+        g_thread_http_workers.emplace_back(HTTPWorkQueueRun, workQueue, i);
     }
 }
 

src/init.cpp

@@ -41,6 +41,7 @@
 #include <script/sigcache.h>
 #include <scheduler.h>
 #include <shutdown.h>
+#include <util/threadnames.h>
 #include <timedata.h>
 #include <txdb.h>
 #include <txmempool.h>
@@ -206,7 +207,7 @@ void Shutdown(InitInterfaces& interfaces)
     /// for example if the data directory was found to be locked.
     /// Be sure that anything that writes files or flushes caches only does this if the respective
     /// module was initialized.
-    RenameThread("bitcoin-shutoff");
+    util::ThreadRename("shutoff");
     mempool.AddTransactionsUpdated(1);
 
     StopHTTPRPC();
@@ -506,6 +507,7 @@ void SetupServerArgs()
     gArgs.AddArg("-debugexclude=<category>", strprintf("Exclude debugging information for a category. Can be used in conjunction with -debug=1 to output debug logs for all categories except one or more specified categories."), false, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), false, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), false, OptionsCategory::DEBUG_TEST);
+    gArgs.AddArg("-logthreadnames", strprintf("Prepend debug output with name of the originating thread (only available on platforms supporting thread_local) (default: %u)", DEFAULT_LOGTHREADNAMES), false, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), true, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-mocktime=<n>", "Replace actual time with <n> seconds since epoch (default: 0)", true, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-maxsigcachesize=<n>", strprintf("Limit sum of signature cache and script execution cache sizes to <n> MiB (default: %u)", DEFAULT_MAX_SIG_CACHE_SIZE), true, OptionsCategory::DEBUG_TEST);
@@ -666,7 +668,7 @@ static void CleanupBlockRevFiles()
 static void ThreadImport(std::vector<fs::path> vImportFiles)
 {
     const CChainParams& chainparams = Params();
-    RenameThread("bitcoin-loadblk");
+    util::ThreadRename("loadblk");
     ScheduleBatchPriority();
 
     {
@@ -862,6 +864,7 @@ void InitLogging()
     LogInstance().m_print_to_console = gArgs.GetBoolArg("-printtoconsole", !gArgs.GetBoolArg("-daemon", false));
     LogInstance().m_log_timestamps = gArgs.GetBoolArg("-logtimestamps", DEFAULT_LOGTIMESTAMPS);
     LogInstance().m_log_time_micros = gArgs.GetBoolArg("-logtimemicros", DEFAULT_LOGTIMEMICROS);
+    LogInstance().m_log_threadnames = gArgs.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES);
 
     fLogIPs = gArgs.GetBoolArg("-logips", DEFAULT_LOGIPS);
 
@@ -1286,7 +1289,7 @@ bool AppInitMain(InitInterfaces& interfaces)
     LogPrintf("Using %u threads for script verification\n", nScriptCheckThreads);
     if (nScriptCheckThreads) {
         for (int i=0; i<nScriptCheckThreads-1; i++)
-            threadGroup.create_thread(&ThreadScriptCheck);
+            threadGroup.create_thread([i]() { return ThreadScriptCheck(i); });
     }
 
     // Start the lightweight task scheduler thread

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,29 +199,32 @@ 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) {
         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(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);
         }
     }
 }

src/logging.h

@@ -19,6 +19,7 @@
 static const bool DEFAULT_LOGTIMEMICROS = false;
 static const bool DEFAULT_LOGIPS        = false;
 static const bool DEFAULT_LOGTIMESTAMPS = true;
+static const bool DEFAULT_LOGTHREADNAMES = false;
 extern const char * const DEFAULT_DEBUGLOGFILE;
 
 extern bool fLogIPs;
@@ -81,6 +82,7 @@ namespace BCLog {
 
         bool m_log_timestamps = DEFAULT_LOGTIMESTAMPS;
         bool m_log_time_micros = DEFAULT_LOGTIMEMICROS;
+        bool m_log_threadnames = DEFAULT_LOGTHREADNAMES;
 
         fs::path m_file_path;
         std::atomic<bool> m_reopen_file{false};

src/qt/bitcoin.cpp

@@ -30,6 +30,7 @@
 #include <interfaces/handler.h>
 #include <interfaces/node.h>
 #include <noui.h>
+#include <util/threadnames.h>
 #include <rpc/server.h>
 #include <ui_interface.h>
 #include <uint256.h>
@@ -149,6 +150,7 @@ void BitcoinCore::initialize()
     try
     {
         qDebug() << __func__ << ": Running initialization in thread";
+        util::ThreadRename("qt-init");
         bool rv = m_node.appInitMain();
         Q_EMIT initializeResult(rv);
     } catch (const std::exception& e) {
@@ -423,6 +425,7 @@ int GuiMain(int argc, char* argv[])
     std::tie(argc, argv) = winArgs.get();
 #endif
     SetupEnvironment();
+    util::ThreadRename("main");
 
     std::unique_ptr<interfaces::Node> node = interfaces::MakeNode();
 

src/sync.cpp

@@ -3,9 +3,11 @@
 // file COPYING or http://www.opensource.org/licenses/mit-license.php.
 
 #include <sync.h>
+#include <tinyformat.h>
 
 #include <logging.h>
 #include <util/strencodings.h>
+#include <util/threadnames.h>
 
 #include <stdio.h>
 
@@ -37,23 +39,30 @@ void PrintLockContention(const char* pszName, const char* pszFile, int nLine)
 //
 
 struct CLockLocation {
-    CLockLocation(const char* pszName, const char* pszFile, int nLine, bool fTryIn)
-    {
-        mutexName = pszName;
-        sourceFile = pszFile;
-        sourceLine = nLine;
-        fTry = fTryIn;
-    }
+    CLockLocation(
+        const char* pszName,
+        const char* pszFile,
+        int nLine,
+        bool fTryIn,
+        const std::string& thread_name)
+        : fTry(fTryIn),
+          mutexName(pszName),
+          sourceFile(pszFile),
+          m_thread_name(thread_name),
+          sourceLine(nLine) {}
 
     std::string ToString() const
     {
-        return mutexName + "  " + sourceFile + ":" + itostr(sourceLine) + (fTry ? " (TRY)" : "");
+        return tfm::format(
+            "%s %s:%s%s (in thread %s)",
+            mutexName, sourceFile, itostr(sourceLine), (fTry ? " (TRY)" : ""), m_thread_name);
     }
 
 private:
     bool fTry;
     std::string mutexName;
     std::string sourceFile;
+    const std::string& m_thread_name;
     int sourceLine;
 };
 
@@ -125,7 +134,7 @@ static void push_lock(void* c, const CLockLocation& locklocation)
         std::pair<void*, void*> p1 = std::make_pair(i.first, c);
         if (lockdata.lockorders.count(p1))
             continue;
-        lockdata.lockorders[p1] = g_lockstack;
+        lockdata.lockorders.emplace(p1, g_lockstack);
 
         std::pair<void*, void*> p2 = std::make_pair(c, i.first);
         lockdata.invlockorders.insert(p2);
@@ -141,7 +150,7 @@ static void pop_lock()
 
 void EnterCritical(const char* pszName, const char* pszFile, int nLine, void* cs, bool fTry)
 {
-    push_lock(cs, CLockLocation(pszName, pszFile, nLine, fTry));
+    push_lock(cs, CLockLocation(pszName, pszFile, nLine, fTry, util::ThreadGetInternalName()));
 }
 
 void LeaveCritical()

src/test/setup_common.cpp

@@ -94,7 +94,7 @@ TestingSetup::TestingSetup(const std::string& chainName) : BasicTestingSetup(cha
 
     nScriptCheckThreads = 3;
     for (int i = 0; i < nScriptCheckThreads - 1; i++)
-        threadGroup.create_thread(&ThreadScriptCheck);
+        threadGroup.create_thread([i]() { return ThreadScriptCheck(i); });
 
     g_banman = MakeUnique<BanMan>(GetDataDir() / "banlist.dat", nullptr, DEFAULT_MISBEHAVING_BANTIME);
     g_connman = MakeUnique<CConnman>(0x1337, 0x1337); // Deterministic randomness for tests.