Thread names in logs and deadlock debug tools by jamesob · Pull Request #15849 · bitcoin/bitcoin

jamesob · 2019-04-18T21:14:46Z

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

DrahtBot · 2019-04-18T21:25:06Z

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#15606 ([experimental] UTXO snapshots by jamesob)
#15493 (rfc: Add -printconfig arg to bitcoind by promag)
#15382 ([util] add runCommandParseJSON by Sjors)
#13751 (Utils and libraries: Drops the boost/algorithm/string/split.hpp dependency by 251Labs)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

practicalswift · 2019-04-23T11:33:05Z

Concept ACK

src/logging.cpp

src/sync.cpp

ryanofsky

utACK 503c1ff. Looks like some windows tests are failing, but nothing to do with this PR. I left a few suggestions for changes, but please ignore any that do not sound like super great and wonderful ideas.

configure.ac

src/Makefile.am

src/threadutil.h

ryanofsky · 2019-04-26T16:48:55Z

src/threadutil.cpp

+//! internal name.
+static void SetThreadName(const char* name)
+{
+#if defined(PR_SET_NAME)


In commit "threads: introduce threadutil, refactor thread naming" (91cc480)

Note: Maybe obvious, but just in case it helps other reviewers, this code is unchanged (easy to verify with git log -p -n1 --color-moved=dimmed_zebra)

ryanofsky · 2019-04-26T16:55:18Z

src/logging.cpp


 #include <logging.h>
 #include <util/time.h>
+#include <threadutil.h>


In commit "threads: prefix log messages with thread names" (4fba3ea)

Could sort alphabetically (thread before util)

src/sync.cpp

src/logging.cpp

Note that this doesn't affect anything unless DEBUG_LOCKCONTENTION is defined. See discussions here: - bitcoin#11722 (review) - bitcoin#13168 (comment)

jamesob · 2019-04-26T19:05:51Z

@ryanofsky thanks very much for the review. Per usual, your suggested changes are indelibly righteous. I've made all of them save for the last I commented on.

jamesob · 2019-04-26T20:00:19Z

Reran benchmarking; no performance difference.

absolute

name	iterations	master	threadnames2.18
build.make.23.clang	1	135.8741 (± 0.0000)	133.9639 (± 0.0000)
build.make.23.clang.mem-usage	1	648692.0000 (± 0.0000)	646632.0000 (± 0.0000)
ibd.local.500000.504000.dbcache=2048	3	357.4552 (± 1.2016)	357.3936 (± 1.1932)
ibd.local.500000.504000.dbcache=2048.mem-usage	3	2240597.3333 (± 3291.6968)	2237538.6667 (± 4462.0143)

relative

name	iterations	master	threadnames2.18
build.make.23.clang	1	1.014	1
build.make.23.clang.mem-usage	1	1.003	1
ibd.local.500000.504000.dbcache=2048	3	1.000	1
ibd.local.500000.504000.dbcache=2048.mem-usage	3	1.001	1

ryanofsky

utACK 2e53d90. Just various suggested changes since last review.

src/util/threadnames.cpp

src/util/threadnames.h

jamesob · 2019-04-26T20:26:39Z

@ryanofsky Oops! Thanks, pushed.

ryanofsky

utACK eed4a5c. Reference to temporary bug's fixed now. There is still the lint problem causing travis to fail, though (https://travis-ci.org/bitcoin/bitcoin/jobs/525122780#L356).

maflcko

utACK 043a387

Just some style comments that should probably be ignored

src/test/util_threadnames_tests.cpp

doc/release-notes-pr13168.md

src/logging.cpp

jamesob · 2019-04-27T00:27:53Z

Latest benchmark; 0.7% difference seems attributable to noise.

Empact · 2019-04-27T08:22:51Z

utACK 0cfcb8d

nit: if I'm not mistaken you can use rvalues and move to avoid copies of the name throughout (channeling @sipa) #13168 (comment)

diff --git a/src/util/threadnames.cpp b/src/util/threadnames.cpp
index 3217855f7..2ca91613c 100644
--- a/src/util/threadnames.cpp
+++ b/src/util/threadnames.cpp
@@ -40,18 +40,18 @@ 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(const std::string& name) { g_thread_name = name; }
+static void SetInternalName(std::string&& name) { g_thread_name = 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(const std::string& name) { }
+static void SetInternalName(std::string&& name) { }
 #endif
 
-void util::ThreadRename(const std::string& name)
+void util::ThreadRename(std::string&& name)
 {
     SetThreadName(("bitcoin-" + name).c_str());
-    SetInternalName(name);
+    SetInternalName(std::move(name));
 }
diff --git a/src/util/threadnames.h b/src/util/threadnames.h
index ecf6c50cc..aaf07b9bf 100644
--- a/src/util/threadnames.h
+++ b/src/util/threadnames.h
@@ -10,7 +10,7 @@
 namespace util {
 //! Rename a thread both in terms of an internal (in-memory) name as well
 //! as its system thread name.
-void ThreadRename(const std::string&);
+void ThreadRename(std::string&&);
 
 //! Get the thread's internal (in-memory) name; used e.g. for identification in
 //! logging.

jamesob · 2019-04-27T12:31:57Z

@Empact thanks, pushed.

practicalswift · 2019-04-27T16:49:34Z

I'm not sure the change from const std::string& to std::string&& is an improvement TBH.

It brings no performance benefit in this case AFAICT and const std::string& is what we're using in the rest of the code base.

$ git grep -E 'const std::string( |)&' | wc -l
851
$ git grep -E 'std::string( |)&&' | wc -l
0

Empact · 2019-04-27T21:10:04Z

@practicalswift Rvalues make sense in cases where you have setters or constructors which can consume / incorporate the object passed in. We're not using it with string but you can see other uses here:

$ git grep -E '[a-z]&&' | wc -l
44

If you're not seeing a performance benefit, it could be because my patch is apparently missing one move, as per: https://www.chromium.org/rvalue-references#TOC-9.-Move-constructors-should-be-accompanied-by-move-assignment-operators.

-static void SetInternalName(std::string&& name) { g_thread_name = name; }
+static void SetInternalName(std::string&& name) { g_thread_name = std::move(name); }

I don't think this is critical, but it seems semantically appropriate.

ryanofsky

utACK 4b4bc00. Only changes since last review are disabling by default and adding const and &&.

re: #15849 (comment)

I'm not sure the change from const std::string& to std::string&& is an improvement TBH.

I also wouldn't consider this an improvement because now you can't call SetInternalName with an lvalue (plain variable or reference). This is now an error:

std::string name = "something";
SetInternalName(name);

People get really confused about this stuff, but if the goal is to just move-enable SetInternalName, it should take plain std::string not const std::string&, and not std::string&&.

If a function just needs to read an argument (and not manipulate it before throwing it away or move it into a data structure) it should take const T&.
If a function wants to give callers the option of moving from an argument but still allow copies, it should take plain T.
If a function wants to force callers to move it should take T &&.

doc/release-notes-pr13168.md

src/sync.cpp

src/util/threadnames.cpp

jnewbery · 2019-04-30T18:44:11Z

This is great. Very nicely structured PR and excellent commit messages 🙌

utACK 8722e54

The functional tests should be updated to have this enabled by default:

bitcoin/test/functional/test_framework/test_node.py

Line 83 in 10ed4df

self.args = [

maflcko · 2019-04-30T19:24:21Z

re-utACK 8722e54 (Only change since my previous review is DEFAULT_LOGTHREADNAMES=false and stylistic updates

Show signature and timestamp

Signature:

Timestamp of file with hash 191793320e418666d66ac3696420980055c8e7f889470d345e05c3e4669b7398 -

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

jonasschnelli · 2019-05-02T08:58:11Z

configure.ac

+      *darwin*)
+        # TODO enable thread_local on later versions of Darwin where it is
+        # supported (per https://stackoverflow.com/a/29929949)
+        AC_MSG_RESULT(no)


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

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

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.

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.

@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.

Summary: Backport of core [[bitcoin/bitcoin#15849 | PR15849]]. The first commit disables `thread_local` on some platforms and is not ported: - The Darwin exclusion is no longer needed since D5514. - The MinGw exclusion does not seem necessary, at least with our version. The tests run fine on Windows, both 32 and 64 bits. Also see D2219 which removes the `thread_local` check. This introduces a number of bugs: - This is breaking the build for some *BSD. - This makes some Unix tools inefficient, like `ps` or `killall`. - Some thread names are truncated and cannot be differentiated. The fixes will be ported in their own diff for readability. Test Plan: ninja check make check Run the Gitian builds. Run test_bitcoin.exe on Windows (32 bits) for sanity. Builld and run the tests on OSX. Start `bitcoind` with `-logthreadnames=1` and check the debug log contains the thread names. Reviewers: #bitcoin_abc, jasonbcox Reviewed By: #bitcoin_abc, jasonbcox Subscribers: jasonbcox Differential Revision: https://reviews.bitcoinabc.org/D5540

Summary: This is a follow-up for D5540. Despite the tests passing, the diff is causing bitcoin-qt to fail quickly. Disabling thread_local for this compiler fixes the issue. The code is extracted from [[bitcoin/bitcoin#15849 | PR15849]], but the tests for thread_local is a simplified version. Test Plan: Build for win32 with autotools and cmake. Run bitcoin-qt and check it doesn't crash. As a sanity check, build for win64 and any linux and check `thread_local` is enabled. Reviewers: #bitcoin_abc, jasonbcox Reviewed By: #bitcoin_abc, jasonbcox Subscribers: jasonbcox Differential Revision: https://reviews.bitcoinabc.org/D5587

Thread names in logs and deadlock debug tools See merge request bitcoin-cash-node/bitcoin-cash-node!834 This is a backport of [PR15849](bitcoin/bitcoin#15849) (Thread names in logs and deadlock debug tools). See original PR for benchmarks. Also includes some smaller follow-up PR's: * [PR15968](bitcoin/bitcoin#15968) - Fix portability issue with pthreads * [PR16984](bitcoin/bitcoin#16984) - util: Make thread names shorter * [PR17038](bitcoin/bitcoin#17038) - Don't rename main thread at process level ## Test plan New tests: `ninja check` Run with `-logthreadnames`, observe lines are prefixed with thread ``` 2020-10-28T11:39:16Z [init] init message: Done loading 2020-10-28T11:39:16Z [opencon] opencon thread start 2020-10-28T11:39:16Z [dnsseed] 0 addresses found from DNS seeds 2020-10-28T11:39:16Z [msghand] msghand thread start 2020-10-28T11:39:16Z [dnsseed] dnsseed thread exit ``` Compile with lockorder debugging enabled: `cmake -GNinja -DCMAKE_BUILD_TYPE=Debug ..`

Co-authored-by: UdjinM6 <[email protected]>

partial bitcoin#15842, merge bitcoin#15849, bitcoin#17342, bitcoin#18710: Add local thread pool to CCheckQueue

jamesob force-pushed the 2018-05-threadnames-take-2 branch from 16f551c to a0ca62b Compare April 18, 2019 21:22

fanquake added the Utils/log/libs label Apr 18, 2019

promag mentioned this pull request Apr 21, 2019

Failure in wallet_import_rescan.py #15865

Closed

practicalswift reviewed Apr 25, 2019

View reviewed changes

src/logging.cpp Outdated Show resolved Hide resolved

src/sync.cpp Outdated Show resolved Hide resolved

jamesob force-pushed the 2018-05-threadnames-take-2 branch from a0ca62b to 503c1ff Compare April 26, 2019 13:56

ryanofsky approved these changes Apr 26, 2019

View reviewed changes

disable HAVE_THREAD_LOCAL on unreliable platforms

188ca75

Note that this doesn't affect anything unless DEBUG_LOCKCONTENTION is defined. See discussions here: - bitcoin#11722 (review) - bitcoin#13168 (comment)

jamesob force-pushed the 2018-05-threadnames-take-2 branch from 503c1ff to 28198a7 Compare April 26, 2019 19:04

jamesob force-pushed the 2018-05-threadnames-take-2 branch from 28198a7 to 2e53d90 Compare April 26, 2019 20:03

ryanofsky approved these changes Apr 26, 2019

View reviewed changes

src/util/threadnames.cpp Outdated Show resolved Hide resolved

src/util/threadnames.h Outdated Show resolved Hide resolved

jamesob force-pushed the 2018-05-threadnames-take-2 branch from 2e53d90 to eed4a5c Compare April 26, 2019 20:26

ryanofsky approved these changes Apr 26, 2019

View reviewed changes

jamesob force-pushed the 2018-05-threadnames-take-2 branch from eed4a5c to 043a387 Compare April 26, 2019 21:16

maflcko approved these changes Apr 26, 2019

View reviewed changes

src/test/util_threadnames_tests.cpp Outdated Show resolved Hide resolved

doc/release-notes-pr13168.md Outdated Show resolved Hide resolved

src/logging.cpp Show resolved Hide resolved

jamesob force-pushed the 2018-05-threadnames-take-2 branch from 043a387 to 0cfcb8d Compare April 26, 2019 22:47

jamesob force-pushed the 2018-05-threadnames-take-2 branch from 0cfcb8d to 4b4bc00 Compare April 27, 2019 12:24

ryanofsky approved these changes Apr 29, 2019

View reviewed changes

doc/release-notes-pr13168.md Outdated Show resolved Hide resolved

maflcko reviewed Apr 29, 2019

View reviewed changes

src/sync.cpp Outdated Show resolved Hide resolved

maflcko reviewed Apr 29, 2019

View reviewed changes

src/util/threadnames.cpp Outdated Show resolved Hide resolved

maflcko mentioned this pull request Apr 29, 2019

doc: Explain how to pass in non-fundamental types into functions #15922

Merged

maflcko merged commit 8722e54 into bitcoin:master Apr 30, 2019

jonasschnelli reviewed May 2, 2019

View reviewed changes

maflcko mentioned this pull request May 6, 2019

32 bit linux gitian build fails with "symbol __cxa_thread_atexit_impl from unsupported version GLIBC_2.18" #15958

Closed

jamesob mentioned this pull request May 10, 2019

Renamed bitcoind daemonized process #16007

Closed

maflcko mentioned this pull request May 20, 2019

bitcoind on freebsd prints "__cxa_thread_call_dtors: dtr 0x801a85a40 from unloaded dso, skipping" #16055

Closed

jamesob mentioned this pull request May 20, 2019

configure: Fix thread_local detection #16059

Merged

Sjors mentioned this pull request Aug 9, 2019

Build previous releases and run functional tests #12134

Merged

fanquake mentioned this pull request Apr 7, 2021

Thread names in logs and deadlock debug tools (take 2) #13168

Closed

kwvg mentioned this pull request Jun 5, 2021

partial #15842, merge #15849, #17342, #18710: Add local thread pool to CCheckQueue dashpay/dash#4191

Merged

kwvg added a commit to kwvg/dash that referenced this pull request Jun 25, 2021

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

3f8caf0

Co-authored-by: UdjinM6 <[email protected]>

UdjinM6 added a commit to dashpay/dash that referenced this pull request Jun 26, 2021

Merge pull request #4191 from kittywhiskers/checkqueue

c5cc285

partial bitcoin#15842, merge bitcoin#15849, bitcoin#17342, bitcoin#18710: Add local thread pool to CCheckQueue

bitcoin locked as resolved and limited conversation to collaborators Dec 16, 2021

Conversation

jamesob commented Apr 18, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

threadnames off (default)

2018-05-threadnames.3 vs. master (absolute)

2018-05-threadnames.3 vs. master (relative)

threadnames on

2018-05-threadnames-take-2 vs. master (absolute)

2018-05-threadnames-take-2 vs. master (relative)

Uh oh!

DrahtBot commented Apr 18, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

practicalswift commented Apr 23, 2019

Uh oh!

Uh oh!

Uh oh!

ryanofsky left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ryanofsky Apr 26, 2019

Choose a reason for hiding this comment

Uh oh!

ryanofsky Apr 26, 2019

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

jamesob commented Apr 26, 2019

Uh oh!

jamesob commented Apr 26, 2019

absolute

relative

Uh oh!

ryanofsky left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

jamesob commented Apr 26, 2019

Uh oh!

ryanofsky left a comment

Choose a reason for hiding this comment

Uh oh!

maflcko left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

jamesob commented Apr 27, 2019

Uh oh!

Empact commented Apr 27, 2019

Uh oh!

jamesob commented Apr 27, 2019

Uh oh!

practicalswift commented Apr 27, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Empact commented Apr 27, 2019

Uh oh!

ryanofsky left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

jnewbery commented Apr 30, 2019

Uh oh!

maflcko commented Apr 30, 2019

Uh oh!

jonasschnelli May 2, 2019

jamesob commented Apr 18, 2019 •

edited

Loading

DrahtBot commented Apr 18, 2019 •

edited

Loading

practicalswift commented Apr 27, 2019 •

edited

Loading

ryanofsky left a comment •

edited

Loading