Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Thread names in logs and deadlock debug tools #15849

Merged
merged 5 commits into from Apr 30, 2019
Merged
Diff settings

Always

Just for now

@@ -827,8 +827,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
This conversation was marked as resolved by jamesob

This comment has been minimized.

Copy link
@ryanofsky

ryanofsky Apr 26, 2019

Contributor

In commit "disable thread_local on unreliable platforms" (c1d1599)

Commit message is misleading. It sounds like this disables the thread_local keyword when actually it disables the HAVE_THREAD_LOCAL macro. Would suggest: "disable HAVE_THREAD_LOCAL on unreliable platforms" and mentioning that this doesn't affect anything except the DEBUG_LOCKCONTENTION implementation.

*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)

This comment has been minimized.

Copy link
@jonasschnelli

jonasschnelli May 2, 2019

Member

Why can't we check with something like:

AC_MSG_CHECKING([for thread_local support])
AC_LINK_IFELSE([AC_LANG_SOURCE([
  #include <thread>
  static thread_local int foo = 0;
  static void run_thread() { foo++;}
  int main(){
  for(int i = 0; i < 10; i++) { std::thread(run_thread).detach();}
  return foo;
  }
  ])],
  [
    AC_DEFINE(HAVE_THREAD_LOCAL,1,[Define if thread_local is supported.])
    AC_MSG_RESULT(yes)
  ],
  [
    AC_MSG_RESULT(no)
  ]
)

This comment has been minimized.

Copy link
@jamesob

jamesob May 2, 2019

Author Member

Because bad thread_local behavior sometimes doesn't fail explicitly on certain platforms (e.g. mingw32) until execution, and only under certain circumstances.

This comment has been minimized.

Copy link
@jonasschnelli

jonasschnelli May 2, 2019

Member

Can you elaborate a little bit what "bad behavior" exactly mean?
I assume the AC_LINK_IFELSE test would work on OSX,.. right? Or would it be a problem for our depends OSX build where we build with SDK 10.11 but allow min os version of 10.10?

Maybe I just open a PR and test it a bit.

This comment has been minimized.

Copy link
@MarcoFalke

MarcoFalke May 2, 2019

Member

Yeah, I couldn't add thread_local to the tests because of issues with macos: #14985

Might be solved by your AC_LINK check, but disabling it seems safer than running into issues later on.

This comment has been minimized.

Copy link
@jamesob

jamesob May 3, 2019

Author Member

@jonasschnelli see the gist I link to in the code comment above (https://gist.github.com/jamesob/fe9a872051a88b2025b1aa37bfa98605). This example compiles but stackoverflows when run, and I had to specially construct that example IIRC because trivial usages worked okay.

;;
*)
AC_DEFINE(HAVE_THREAD_LOCAL,1,[Define if thread_local is supported.])
AC_MSG_RESULT(yes)
;;
esac
],
[
AC_MSG_RESULT(no)
@@ -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`.
@@ -210,6 +210,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 \
@@ -491,6 +492,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 \
@@ -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 \
@@ -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
//
@@ -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);
}
}

@@ -42,6 +42,7 @@
#include <script/sigcache.h>
#include <scheduler.h>
#include <shutdown.h>
#include <util/threadnames.h>
#include <timedata.h>
#include <txdb.h>
#include <txmempool.h>
@@ -208,7 +209,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();
@@ -507,6 +508,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);
@@ -669,7 +671,7 @@ static void CleanupBlockRevFiles()
static void ThreadImport(std::vector<fs::path> vImportFiles)
{
const CChainParams& chainparams = Params();
RenameThread("bitcoin-loadblk");
util::ThreadRename("loadblk");
ScheduleBatchPriority();

{
@@ -865,6 +867,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);

@@ -1305,7 +1308,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
@@ -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() + "] ");
This conversation was marked as resolved by jamesob

This comment has been minimized.

Copy link
@MarcoFalke

MarcoFalke Apr 26, 2019

Member

style-nit: in commit 951769c threads: prefix log messages with thread names

Could add {}, according to developer notes for new code?

This comment has been minimized.

Copy link
@jamesob

jamesob Apr 26, 2019

Author Member

Done, thanks.

}

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);
}
}
}
@@ -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};
@@ -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();

@@ -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()
@@ -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.
Oops, something went wrong.
ProTip! Use n and p to navigate between commits in a pull request.
You can’t perform that action at this time.