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

Co-authored-by: UdjinM6 <UdjinM6@users.noreply.github.com>
This commit is contained in:
Kittywhiskers Van Gogh 2021-06-24 23:24:20 +05:30
parent a612ec5087
commit 3f8caf00bc
18 changed files with 233 additions and 97 deletions

View File

@ -865,8 +865,23 @@ AC_LINK_IFELSE([AC_LANG_SOURCE([
}
])],
[
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)

View File

@ -265,6 +265,7 @@ BITCOIN_CORE_H = \
utilmoneystr.h \
utilstring.h \
utiltime.h \
utilthreadnames.h \
validation.h \
validationinterface.h \
versionbits.h \
@ -591,6 +592,7 @@ libdash_util_a_SOURCES = \
utilstrencodings.cpp \
utiltime.cpp \
utilstring.cpp \
utilthreadnames.cpp \
$(BITCOIN_CORE_H)
if GLIBC_BACK_COMPAT

View File

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

View File

@ -19,6 +19,7 @@
#include <httpserver.h>
#include <httprpc.h>
#include <utilstrencodings.h>
#include <utilthreadnames.h>
#include <walletinitinterface.h>
#include <stacktraces.h>
@ -57,6 +58,8 @@ static bool AppInit(int argc, char* argv[])
{
bool fRet = false;
util::ThreadRename("init");
//
// Parameters
//

View File

@ -9,6 +9,7 @@
#include <compat.h>
#include <util.h>
#include <utilstrencodings.h>
#include <utilthreadnames.h>
#include <netbase.h>
#include <rpc/protocol.h> // For HTTP status codes
#include <sync.h>
@ -18,7 +19,7 @@
#include <memory>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <string>
#include <sys/types.h>
#include <sys/stat.h>
@ -286,7 +287,7 @@ static void http_reject_request_cb(struct evhttp_request* req, void*)
/** Event dispatcher thread */
static bool ThreadHTTP(struct event_base* base, struct evhttp* http)
{
RenameThread("dash-http");
util::ThreadRename("http");
LogPrint(BCLog::HTTP, "Entering http event loop\n");
event_base_dispatch(base);
// Event loop will be interrupted by InterruptHTTPServer()
@ -337,9 +338,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("dash-httpworker");
util::ThreadRename(strprintf("httpworker.%i", worker_num));
queue->Run();
}
@ -440,7 +441,7 @@ bool StartHTTPServer()
threadHTTP = std::thread(ThreadHTTP, eventBase, eventHTTP);
for (int i = 0; i < rpcThreads; i++) {
g_thread_http_workers.emplace_back(HTTPWorkQueueRun, workQueue);
g_thread_http_workers.emplace_back(HTTPWorkQueueRun, workQueue, i);
}
return true;
}

View File

@ -39,6 +39,7 @@
#include <script/standard.h>
#include <script/sigcache.h>
#include <scheduler.h>
#include <utilthreadnames.h>
#include <timedata.h>
#include <txdb.h>
#include <txmempool.h>
@ -243,7 +244,7 @@ void PrepareShutdown()
/// 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("dash-shutoff");
util::ThreadRename("shutoff");
mempool.AddTransactionsUpdated(1);
StopHTTPRPC();
StopREST();
@ -606,12 +607,12 @@ void SetupServerArgs()
gArgs.AddArg("-llmqinstantsend=<quorum name>", strprintf("Override the default LLMQ type used for InstantSend on a devnet. Allows using InstantSend with smaller LLMQs. (default: %s)", devnetConsensus.llmqs.at(devnetConsensus.llmqTypeInstantSend).name), false, OptionsCategory::DEBUG_TEST);
gArgs.AddArg("-llmqtestparams=<size:threshold>", strprintf("Override the default LLMQ size for the LLMQ_TEST quorum (default: %u:%u)", regtestLLMQ.size, regtestLLMQ.threshold), false, OptionsCategory::DEBUG_TEST);
gArgs.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), false, OptionsCategory::DEBUG_TEST);
gArgs.AddArg("-logthreadnames", strprintf("Add thread names to debug messages (default: %u)", DEFAULT_LOGTHREADNAMES), true, OptionsCategory::DEBUG_TEST);
gArgs.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), true, 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), 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);
gArgs.AddArg("-maxtipage=<n>", strprintf("Maximum tip age in seconds to consider node in initial block download (default: %u)", DEFAULT_MAX_TIP_AGE), true, OptionsCategory::DEBUG_TEST);
gArgs.AddArg("-mocktime=<n>", "Replace actual time with <n> seconds since epoch (default: 0)", true, OptionsCategory::DEBUG_TEST);
gArgs.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), false, OptionsCategory::DEBUG_TEST);
gArgs.AddArg("-maxtxfee=<amt>", strprintf("Maximum total fees (in %s) to use in a single wallet transaction or raw transaction; setting this too low may abort large transactions (default: %s)",
CURRENCY_UNIT, FormatMoney(DEFAULT_TRANSACTION_MAXFEE)), false, OptionsCategory::DEBUG_TEST);
gArgs.AddArg("-minimumdifficultyblocks=<n>", strprintf("The number of blocks that can be mined with the minimum difficulty at the start of a devnet (default: %u)", devnetConsensus.nMinimumDifficultyBlocks), false, OptionsCategory::DEBUG_TEST);
@ -774,7 +775,7 @@ static void CleanupBlockRevFiles()
static void ThreadImport(std::vector<fs::path> vImportFiles)
{
const CChainParams& chainparams = Params();
RenameThread("dash-loadblk");
util::ThreadRename("loadblk");
ScheduleBatchPriority();
{
@ -1092,7 +1093,7 @@ void InitLogging()
g_logger->m_print_to_console = gArgs.GetBoolArg("-printtoconsole", !gArgs.GetBoolArg("-daemon", false));
g_logger->m_log_timestamps = gArgs.GetBoolArg("-logtimestamps", DEFAULT_LOGTIMESTAMPS);
g_logger->m_log_time_micros = gArgs.GetBoolArg("-logtimemicros", DEFAULT_LOGTIMEMICROS);
g_logger->m_log_thread_names = gArgs.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES);
g_logger->m_log_threadnames = gArgs.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES);
fLogIPs = gArgs.GetBoolArg("-logips", DEFAULT_LOGIPS);
@ -1731,7 +1732,7 @@ bool AppInitMain()
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); });
}
std::vector<std::string> vSporkAddresses;

View File

@ -5,8 +5,11 @@
#include <logging.h>
#include <util.h>
#include <utilthreadnames.h>
#include <utiltime.h>
#include <mutex>
const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
/**
@ -244,43 +247,29 @@ std::string BCLog::Logger::LogTimestampStr(const std::string &str)
return strStamped;
}
std::string BCLog::Logger::LogThreadNameStr(const std::string &str)
{
std::string strThreadLogged;
if (!m_log_thread_names)
return str;
std::string strThreadName = GetThreadName();
if (m_started_new_line)
strThreadLogged = strprintf("%16s | %s", strThreadName.c_str(), str.c_str());
else
strThreadLogged = str;
return strThreadLogged;
}
void BCLog::Logger::LogPrintStr(const std::string& str)
{
StdLockGuard scoped_lock(m_cs);
std::string strThreadLogged = LogThreadNameStr(str);
std::string strTimestamped = LogTimestampStr(strThreadLogged);
std::string str_prefixed = str;
if (!str.empty() && str[str.size()-1] == '\n')
m_started_new_line = true;
else
m_started_new_line = false;
if (m_log_threadnames && m_started_new_line) {
// 16 chars total, "dash-" is 5 of them and another 1 is a NUL terminator
str_prefixed.insert(0, "[" + strprintf("%10s", util::ThreadGetInternalName()) + "] ");
}
str_prefixed = LogTimestampStr(str_prefixed);
m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
if (m_buffering) {
// buffer if we haven't started logging yet
m_msgs_before_open.push_back(strTimestamped);
m_msgs_before_open.push_back(str_prefixed);
return;
}
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) {
@ -296,7 +285,7 @@ void BCLog::Logger::LogPrintStr(const std::string& str)
m_fileout = new_fileout;
}
}
FileWriteStr(strTimestamped, m_fileout);
FileWriteStr(str_prefixed, m_fileout);
}
}

View File

@ -108,7 +108,7 @@ namespace BCLog {
bool m_log_timestamps = DEFAULT_LOGTIMESTAMPS;
bool m_log_time_micros = DEFAULT_LOGTIMEMICROS;
bool m_log_thread_names = DEFAULT_LOGTHREADNAMES;
bool m_log_threadnames = DEFAULT_LOGTHREADNAMES;
fs::path m_file_path;
std::atomic<bool> m_reopen_file{false};

View File

@ -257,6 +257,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 (...) {
@ -577,6 +578,7 @@ int main(int argc, char *argv[])
RegisterPrettySignalHandlers();
SetupEnvironment();
util::ThreadRename("main");
std::unique_ptr<interfaces::Node> node = interfaces::MakeNode();

View File

@ -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 <utilstrencodings.h>
#include <utilthreadnames.h>
#include <stdio.h>
@ -36,23 +38,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;
};
@ -124,7 +133,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);
@ -140,7 +149,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()

View File

@ -128,7 +128,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); });
peerLogic.reset(new PeerLogicValidation(connman, scheduler, /*enable_bip61=*/true));
}

View File

@ -0,0 +1,73 @@
// 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 <utilthreadnames.h>
#include <test/test_dash.h>
#include <thread>
#include <vector>
#include <set>
#include <mutex>
#if defined(HAVE_CONFIG_H)
#include <config/dash-config.h>
#endif
#include <boost/test/unit_test.hpp>
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<std::string> RenameEnMasse(int num_threads)
{
std::vector<std::thread> threads;
std::set<std::string> names;
std::mutex lock;
auto RenameThisThread = [&](int i) {
util::ThreadRename(TEST_THREAD_NAME_BASE + std::to_string(i));
std::lock_guard<std::mutex> 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(), "");
#if !defined(HAVE_THREAD_LOCAL)
// This test doesn't apply to platforms where we don't have thread_local.
return;
#endif
std::set<std::string> 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()

View File

@ -67,10 +67,6 @@
#include <shlobj.h>
#endif
#ifdef HAVE_SYS_PRCTL_H
#include <sys/prctl.h>
#endif
#ifdef HAVE_MALLOPT_ARENA_MAX
#include <malloc.h>
#endif
@ -1061,38 +1057,6 @@ void runCommand(const std::string& strCommand)
LogPrintf("runCommand error: system(%s) returned %d\n", strCommand, nErr);
}
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
LogPrintf("%s: thread new name %s\n", __func__, name);
}
std::string GetThreadName()
{
char name[16];
#if defined(PR_GET_NAME)
// Only the first 15 characters are used (16 - NUL terminator)
::prctl(PR_GET_NAME, name, 0, 0, 0);
#elif defined(MAC_OSX)
pthread_getname_np(pthread_self(), name, 16);
// #elif (defined(__FreeBSD__) || defined(__OpenBSD__) || defined(__DragonFly__))
// #else
// no get_name here
#endif
return std::string(name);
}
void RenameThreadPool(ctpl::thread_pool& tp, const char* baseName)
{
auto cond = std::make_shared<std::condition_variable>();
@ -1102,7 +1066,7 @@ void RenameThreadPool(ctpl::thread_pool& tp, const char* baseName)
for (int i = 0; i < tp.size(); i++) {
futures[i] = tp.push([baseName, i, cond, mutex, &doneCnt](int threadId) {
RenameThread(strprintf("%s-%d", baseName, i).c_str());
util::ThreadRename(strprintf("%s-%d", baseName, i).c_str());
std::unique_lock<std::mutex> l(*mutex);
doneCnt++;
cond->wait(l);

View File

@ -20,6 +20,7 @@
#include <fs.h>
#include <logging.h>
#include <sync.h>
#include <utilthreadnames.h>
#include <tinyformat.h>
#include <utiltime.h>
#include <utilmemory.h>
@ -326,9 +327,6 @@ std::string HelpMessageOpt(const std::string& option, const std::string& message
*/
int GetNumCores();
void RenameThread(const char* name);
std::string GetThreadName();
namespace ctpl {
class thread_pool;
}
@ -339,8 +337,7 @@ void RenameThreadPool(ctpl::thread_pool& tp, const char* baseName);
*/
template <typename Callable> void TraceThread(const std::string name, Callable func)
{
std::string s = "dash-" + name;
RenameThread(s.c_str());
util::ThreadRename(name.c_str());
try
{
LogPrintf("%s thread start\n", name);

57
src/utilthreadnames.cpp Normal file
View File

@ -0,0 +1,57 @@
// 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 <config/dash-config.h>
#endif
#include <atomic>
#include <thread>
#include <utilthreadnames.h>
#ifdef HAVE_SYS_PRCTL_H
#include <sys/prctl.h> // 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
}
// If we have thread_local, just keep thread ID and name in a thread_local
// global.
#if defined(HAVE_THREAD_LOCAL)
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); }
// Without thread_local available, don't handle internal name at all.
#else
static const std::string empty_string;
const std::string& util::ThreadGetInternalName() { return empty_string; }
static void SetInternalName(std::string name) { }
#endif
void util::ThreadRename(std::string&& name)
{
SetThreadName(("dash-" + name).c_str());
SetInternalName(std::move(name));
}

21
src/utilthreadnames.h Normal file
View File

@ -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_UTILTHREADNAMES_H
#define BITCOIN_UTILTHREADNAMES_H
#include <string>
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

View File

@ -52,6 +52,7 @@
#include <future>
#include <sstream>
#include <string>
#include <boost/algorithm/string/replace.hpp>
#include <boost/thread.hpp>
@ -1891,8 +1892,8 @@ static bool WriteUndoDataForBlock(const CBlockUndo& blockundo, CValidationState&
static CCheckQueue<CScriptCheck> scriptcheckqueue(128);
void ThreadScriptCheck() {
RenameThread("dash-scriptch");
void ThreadScriptCheck(int worker_num) {
util::ThreadRename(strprintf("scriptch.%i", worker_num));
scriptcheckqueue.Thread();
}

View File

@ -275,7 +275,7 @@ bool LoadChainTip(const CChainParams& chainparams);
/** Unload database information */
void UnloadBlockIndex();
/** 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 or network) */
bool IsInitialBlockDownload();
/** Retrieve a transaction (from memory pool, or from disk, if possible) */