diff --git a/doc/release-notes.md b/doc/release-notes.md --- a/doc/release-notes.md +++ b/doc/release-notes.md @@ -19,3 +19,9 @@ - `-usehd` was removed in version 0.16. From that version onwards, all new wallets created are hierarchical deterministic wallets. Version 0.18 makes specifying `-usehd` invalid config. + +Thread names in logs +-------------------- + +Log lines can be prefixed with the name of the thread that caused the log. +To enable this behavior, use`-logthreadnames=1`. diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -290,11 +290,12 @@ sync.cpp threadinterrupt.cpp uint256.cpp - util/system.cpp + util/bytevectorhash.cpp util/moneystr.cpp util/strencodings.cpp + util/system.cpp + util/threadnames.cpp util/time.cpp - util/bytevectorhash.cpp # obj/build.h "${BUILD_HEADER}" diff --git a/src/Makefile.am b/src/Makefile.am --- a/src/Makefile.am +++ b/src/Makefile.am @@ -213,11 +213,12 @@ txmempool.h \ ui_interface.h \ undo.h \ - util/system.h \ - util/moneystr.h \ - util/time.h \ util/bitmanip.h \ util/bytevectorhash.h \ + util/moneystr.h \ + util/system.h \ + util/threadnames.h \ + util/time.h \ validation.h \ validationinterface.h \ versionbits.h \ @@ -492,6 +493,7 @@ util/system.cpp \ util/moneystr.cpp \ util/strencodings.cpp \ + util/threadnames.cpp \ util/time.cpp \ util/bytevectorhash.cpp \ $(BITCOIN_CORE_H) diff --git a/src/Makefile.test.include b/src/Makefile.test.include --- a/src/Makefile.test.include +++ b/src/Makefile.test.include @@ -174,6 +174,7 @@ 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 \ diff --git a/src/bitcoind.cpp b/src/bitcoind.cpp --- a/src/bitcoind.cpp +++ b/src/bitcoind.cpp @@ -21,6 +21,7 @@ #include #include #include +#include #include #include @@ -72,6 +73,8 @@ bool fRet = false; + util::ThreadRename("init"); + // // Parameters // diff --git a/src/httpserver.cpp b/src/httpserver.cpp --- a/src/httpserver.cpp +++ b/src/httpserver.cpp @@ -16,6 +16,7 @@ #include #include #include +#include #include #include @@ -293,7 +294,7 @@ /** 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() @@ -349,8 +350,8 @@ } /** Simple wrapper to set thread name and run work queue */ -static void HTTPWorkQueueRun(WorkQueue *queue) { - RenameThread("bitcoin-httpworker"); +static void HTTPWorkQueueRun(WorkQueue *queue, int worker_num) { + util::ThreadRename(strprintf("httpworker.%i", worker_num)); queue->Run(); } @@ -461,7 +462,7 @@ 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); } } diff --git a/src/init.cpp b/src/init.cpp --- a/src/init.cpp +++ b/src/init.cpp @@ -48,6 +48,7 @@ #include #include #include +#include #include #include #include @@ -179,7 +180,7 @@ /// failed part of the way, 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"); g_mempool.AddTransactionsUpdated(1); StopHTTPRPC(); @@ -825,7 +826,13 @@ strprintf("Prepend debug output with timestamp (default: %d)", 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: %d)", @@ -1137,7 +1144,7 @@ static void ThreadImport(const Config &config, std::vector vImportFiles) { - RenameThread("bitcoin-loadblk"); + util::ThreadRename("loadblk"); ScheduleBatchPriority(); { @@ -1403,6 +1410,8 @@ 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); @@ -1913,7 +1922,7 @@ nScriptCheckThreads); if (nScriptCheckThreads) { for (int i = 0; i < nScriptCheckThreads - 1; i++) { - threadGroup.create_thread(&ThreadScriptCheck); + threadGroup.create_thread([i]() { return ThreadScriptCheck(i); }); } } diff --git a/src/logging.h b/src/logging.h --- a/src/logging.h +++ b/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 bool fLogIPs; extern const char *const DEFAULT_DEBUGLOGFILE; @@ -81,6 +82,7 @@ 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 m_reopen_file{false}; diff --git a/src/logging.cpp b/src/logging.cpp --- a/src/logging.cpp +++ b/src/logging.cpp @@ -6,8 +6,11 @@ #include +#include #include +#include + bool fLogIPs = DEFAULT_LOGIPS; const char *const DEFAULT_DEBUGLOGFILE = "debug.log"; @@ -166,21 +169,23 @@ 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) { @@ -188,7 +193,7 @@ // 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 { // Reopen the log file, if requested. if (m_reopen_file) { @@ -201,7 +206,7 @@ m_fileout = new_fileout; } } - FileWriteStr(strTimestamped, m_fileout); + FileWriteStr(str_prefixed, m_fileout); } } } diff --git a/src/qt/bitcoin.cpp b/src/qt/bitcoin.cpp --- a/src/qt/bitcoin.cpp +++ b/src/qt/bitcoin.cpp @@ -30,6 +30,7 @@ #include #include #include +#include #include #include @@ -164,6 +165,7 @@ HTTPRPCRequestProcessor *httpRPCRequestProcessor) { try { qDebug() << __func__ << ": Running initialization in thread"; + util::ThreadRename("qt-init"); bool rv = m_node.appInitMain(*config, *rpcServer, *httpRPCRequestProcessor); Q_EMIT initializeResult(rv); @@ -515,6 +517,7 @@ std::tie(argc, argv) = winArgs.get(); #endif SetupEnvironment(); + util::ThreadRename("main"); std::unique_ptr node = interfaces::MakeNode(); diff --git a/src/sync.cpp b/src/sync.cpp --- a/src/sync.cpp +++ b/src/sync.cpp @@ -6,6 +6,9 @@ #include #include +#include + +#include #include #include @@ -33,22 +36,21 @@ struct CLockLocation { CLockLocation(const char *pszName, const char *pszFile, int nLine, - bool fTryIn) { - mutexName = pszName; - sourceFile = pszFile; - sourceLine = nLine; - fTry = fTryIn; - } + 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 +127,7 @@ if (lockdata.lockorders.count(p1)) { continue; } - lockdata.lockorders[p1] = g_lockstack; + lockdata.lockorders.emplace(p1, g_lockstack); std::pair p2 = std::make_pair(c, i.first); lockdata.invlockorders.insert(p2); @@ -142,7 +144,8 @@ 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() { diff --git a/src/test/CMakeLists.txt b/src/test/CMakeLists.txt --- a/src/test/CMakeLists.txt +++ b/src/test/CMakeLists.txt @@ -185,6 +185,7 @@ uint256_tests.cpp undo_tests.cpp util_tests.cpp + util_threadnames_tests.cpp validation_block_tests.cpp validation_tests.cpp versionbits_tests.cpp diff --git a/src/test/setup_common.cpp b/src/test/setup_common.cpp --- a/src/test/setup_common.cpp +++ b/src/test/setup_common.cpp @@ -123,7 +123,7 @@ } nScriptCheckThreads = 3; for (int i = 0; i < nScriptCheckThreads - 1; i++) { - threadGroup.create_thread(&ThreadScriptCheck); + threadGroup.create_thread([i]() { return ThreadScriptCheck(i); }); } g_banman = diff --git a/src/test/util_threadnames_tests.cpp b/src/test/util_threadnames_tests.cpp new file mode 100644 --- /dev/null +++ b/src/test/util_threadnames_tests.cpp @@ -0,0 +1,69 @@ +// Copyright (c) 2018 The Bitcoin Core developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#include + +#if defined(HAVE_CONFIG_H) +#include +#endif + +#include + +#include + +#include +#include +#include +#include + +BOOST_FIXTURE_TEST_SUITE(util_threadnames_tests, BasicTestingSetup) + +const std::string TEST_THREAD_NAME_BASE = "test_thread."; + +/** + * Run a bunch of threads to all call util::ThreadRename. + * + * @return the set of name each thread has after attempted renaming. + */ +std::set RenameEnMasse(int num_threads) { + std::vector threads; + std::set names; + std::mutex lock; + + auto RenameThisThread = [&](int i) { + util::ThreadRename(TEST_THREAD_NAME_BASE + std::to_string(i)); + std::lock_guard guard(lock); + names.insert(util::ThreadGetInternalName()); + }; + + for (int i = 0; i < num_threads; ++i) { + threads.push_back(std::thread(RenameThisThread, i)); + } + + for (std::thread &thread : threads) { + thread.join(); + } + + return names; +} + +/** + * Rename a bunch of threads with the same basename (expect_multiple=true), + * ensuring suffixes are applied properly. + */ +BOOST_AUTO_TEST_CASE(util_threadnames_test_rename_threaded) { + BOOST_CHECK_EQUAL(util::ThreadGetInternalName(), ""); + + std::set names = RenameEnMasse(100); + + BOOST_CHECK_EQUAL(names.size(), 100); + + // Names "test_thread.[n]" should exist for n = [0, 99] + for (int i = 0; i < 100; ++i) { + BOOST_CHECK(names.find(TEST_THREAD_NAME_BASE + std::to_string(i)) != + names.end()); + } +} + +BOOST_AUTO_TEST_SUITE_END() diff --git a/src/util/system.h b/src/util/system.h --- a/src/util/system.h +++ b/src/util/system.h @@ -21,6 +21,7 @@ #include #include #include +#include #include #include // for boost::thread_interrupted @@ -333,14 +334,11 @@ */ int GetNumCores(); -void RenameThread(const char *name); - /** * .. and a wrapper that just calls func once */ template void TraceThread(const char *name, Callable func) { - std::string s = strprintf("bitcoin-%s", name); - RenameThread(s.c_str()); + util::ThreadRename(name); try { LogPrintf("%s thread start\n", name); func(); diff --git a/src/util/system.cpp b/src/util/system.cpp --- a/src/util/system.cpp +++ b/src/util/system.cpp @@ -75,10 +75,6 @@ #include #endif -#ifdef HAVE_SYS_PRCTL_H -#include -#endif - #ifdef HAVE_MALLOPT_ARENA_MAX #include #endif @@ -1268,21 +1264,6 @@ } } -void RenameThread(const char *name) { -#if defined(PR_SET_NAME) - // Only the first 15 characters are used (16 - NUL terminator) - ::prctl(PR_SET_NAME, name, 0, 0, 0); -#elif (defined(__FreeBSD__) || defined(__OpenBSD__) || defined(__DragonFly__)) - pthread_set_name_np(pthread_self(), name); - -#elif defined(MAC_OSX) - pthread_setname_np(name); -#else - // Prevent warnings for unused parameters... - (void)name; -#endif -} - void SetupEnvironment() { #ifdef HAVE_MALLOPT_ARENA_MAX // glibc-specific: On 32-bit systems set the number of arenas to 1. By diff --git a/src/util/threadnames.h b/src/util/threadnames.h new file mode 100644 --- /dev/null +++ b/src/util/threadnames.h @@ -0,0 +1,21 @@ +// Copyright (c) 2018 The Bitcoin Core developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#ifndef BITCOIN_UTIL_THREADNAMES_H +#define BITCOIN_UTIL_THREADNAMES_H + +#include + +namespace util { +//! Rename a thread both in terms of an internal (in-memory) name as well +//! as its system thread name. +void ThreadRename(std::string &&); + +//! Get the thread's internal (in-memory) name; used e.g. for identification in +//! logging. +const std::string &ThreadGetInternalName(); + +} // namespace util + +#endif // BITCOIN_UTIL_THREADNAMES_H diff --git a/src/util/threadnames.cpp b/src/util/threadnames.cpp new file mode 100644 --- /dev/null +++ b/src/util/threadnames.cpp @@ -0,0 +1,46 @@ +// Copyright (c) 2018 The Bitcoin Core developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#if defined(HAVE_CONFIG_H) +#include +#endif + +#include + +#include + +#ifdef HAVE_SYS_PRCTL_H +#include // For prctl, PR_SET_NAME, PR_GET_NAME +#endif + +//! Set the thread's name at the process level. Does not affect the internal +//! name. +static void SetThreadName(const char *name) { +#if defined(PR_SET_NAME) + // Only the first 15 characters are used (16 - NUL terminator) + ::prctl(PR_SET_NAME, name, 0, 0, 0); +#elif (defined(__FreeBSD__) || defined(__OpenBSD__) || defined(__DragonFly__)) + pthread_set_name_np(pthread_self(), name); +#elif defined(MAC_OSX) + pthread_setname_np(name); +#else + // Prevent warnings for unused parameters... + (void)name; +#endif +} + +static thread_local std::string g_thread_name; +const std::string &util::ThreadGetInternalName() { + return g_thread_name; +} +//! Set the in-memory internal name for this thread. Does not affect the process +//! name. +static void SetInternalName(std::string name) { + g_thread_name = std::move(name); +} + +void util::ThreadRename(std::string &&name) { + SetThreadName(("bitcoin-" + name).c_str()); + SetInternalName(std::move(name)); +} diff --git a/src/validation.h b/src/validation.h --- a/src/validation.h +++ b/src/validation.h @@ -383,7 +383,7 @@ /** * Run an instance of the script checking thread. */ -void ThreadScriptCheck(); +void ThreadScriptCheck(int worker_num); /** * Check whether we are doing an initial block download (synchronizing from disk diff --git a/src/validation.cpp b/src/validation.cpp --- a/src/validation.cpp +++ b/src/validation.cpp @@ -54,6 +54,7 @@ #include #include #include +#include #include #include // For debugging @@ -1616,8 +1617,8 @@ static CCheckQueue scriptcheckqueue(128); -void ThreadScriptCheck() { - RenameThread("bitcoin-scriptch"); +void ThreadScriptCheck(int worker_num) { + util::ThreadRename(strprintf("scriptch.%i", worker_num)); scriptcheckqueue.Thread(); }