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

jamesob commented at 9:01 pm on May 4, 2018: member

Replaces #13099.

The goal here is the same as the previous PR, but this approach only includes threadnames in logs when we can make use of thread_local. We specifically disable HAVE_THREAD_LOCAL for platforms where its presence or implementation is questionable (Darwin, mingw32).

Instead of using a mutex-protected map to generate numeric suffixes (e.g. httpworker.2) we explicitly pass in suffixes during thread creation.

Under this changeset, logs look like this:

 02018-06-13T21:43:28Z [bitcoin-qt-init] init message: Starting network threads...
 12018-06-13T21:43:28Z [net] net thread start
 22018-06-13T21:43:28Z [bitcoin-qt-init] init message: Done loading
 32018-06-13T21:43:28Z [opencon] opencon thread start
 42018-06-13T21:43:28Z [msghand] msghand thread start
 52018-06-13T21:43:28Z [dnsseed] dnsseed thread start
 62018-06-13T21:43:28Z [dnsseed] Loading addresses from DNS seeds (could take a while)
 72018-06-13T21:43:28Z [dnsseed] 0 addresses found from DNS seeds
 82018-06-13T21:43:28Z [dnsseed] dnsseed thread exit
 92018-06-13T21:43:28Z [addcon] addcon thread start
102018-06-13T21:43:28Z [bitcoin-qt] GUI: Platform customization: "other"
112018-06-13T21:43:28Z [bitcoin-qt] GUI: PaymentServer::LoadRootCAs: Loaded  146  root certificates
122018-06-13T21:43:28Z [loadblk] Loaded 1 blocks from external file in 147ms
132018-06-13T21:43:28Z [loadblk] Reindexing finished
142018-06-13T21:43:28Z [loadblk] Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there

in src/threadval.cpp:39 in 01e0925b87 outdated

34+
35+    long m_id{0};
36+    std::string m_name{"unnamed"};
37+};
38+
39+#if defined(HAVE_THREAD_LOCAL)

sipa commented at 9:11 pm on May 4, 2018:

Do we want to use thread local even on mingw (where you had problems earlier?)

theuni commented at 9:31 pm on May 4, 2018:

https://github.com/bitcoin/bitcoin/pull/13168/files#diff-defae1c29982e5afaf477729b6c7d9b4R11 :)

in src/threadval.cpp:74 in 01e0925b87 outdated

69+    pthread_key_create(&g_key, destruct_data);
70+}
71+
72+std::string thread_data::get_internal_name()
73+{
74+    void* data = pthread_getspecific(g_key);

sipa commented at 9:16 pm on May 4, 2018:

(in this function and the next) g_key is uninitialized if called before set_internal_name is invoked. Perhaps you need to add the pthread_once call here as well?

If not, document that it’s illegal to invoke these functions without knowing if set_internal_name has been called.

theuni commented at 9:40 pm on May 4, 2018:

Yep, good catch.

in src/threadval.cpp:100 in 01e0925b87 outdated

 95+    void* data = pthread_getspecific(g_key);
 96+    if (data) {
 97+        static_cast<thread_data_type*>(data)->m_name = std::move(name);
 98+        return true;
 99+    }
100+    data = new thread_data_type{internal_id++, std::move(name)};

sipa commented at 9:19 pm on May 4, 2018:

The internal_id has different semantics here than in the thread_local case (here it’s only incremented the first time a thread is given a name; in the above case it’s incremented every time the name changes). Is that an issue?

theuni commented at 9:45 pm on May 4, 2018:

Yep. The thread_local impl is incorrect. We only want to increment if unset, so thread id’s don’t bounce around across renames.

jamesob force-pushed on May 4, 2018

sipa commented at 9:27 pm on May 4, 2018: member

A few nits/comments on the first commit. Also:

Why the rename from threadval to threadutil? Ideally introduce the file with the preferred name in the first commit, or at least do the rename in a separate commit from other changes.
Naming convention (functions should be CamelCase).
get_internal_id seems entirely unused.

jamesob commented at 9:37 pm on May 4, 2018: member

I figure “threadutil” might be a better name going forward because I anticipate as we continue to split stuff out of util, this unit might be a good home for things like TraceThread. If you or @theuni thinks we should stick with “threadval” I’m happy to revert, otherwise I’ll split out the rename into a separate commit.

sipa commented at 9:38 pm on May 4, 2018: member

@jamesob I have no opinion about the name. I’m only complaining about a rename in the middle of a PR in a commit that also introduces other changes.

in src/threadutil.cpp:110 in ffa1b4f873 outdated

105+static thread_local thread_data_type g_thread_data;
106+std::string thread_util::get_internal_name()
107+{
108+    auto name = g_thread_data.m_name;
109+
110+    if (g_thread_data.m_name.empty()) {

theuni commented at 9:53 pm on May 4, 2018:

Why the fallback?

jamesob commented at 4:40 pm on May 5, 2018:

There were lots of "<unnamed>" occurrences in the logs and so I figured it made sense to fall back to the process name if we hadn’t explicitly named the thread (e.g. bitcoind, bitcoin-qt). Do you think it makes more sense to just explicitly call rename on those main threads?

jamesob commented at 4:49 pm on May 5, 2018:

I can see concerns with get_internal_name being a misnomer. Maybe we should introduce a GetName that first tries the internal name and then falls back to the process name?

theuni commented at 10:04 pm on May 4, 2018: member

@jamesob You can just take the threadval files, don’t worry about the commit attribution.

Agree with @sipa about the name change, it complicates the review a pretty good bit. Also no preference on naming. I originally named it “threadval” with the intention of making it a generic low-level interface for thread_local, but that’s not worth the trouble.

fanquake added the label Utils/log/libs on May 5, 2018

jamesob force-pushed on May 5, 2018

jamesob commented at 8:17 pm on May 5, 2018: member

@sipa @theuni Thanks for the quick look and comments. I’ve pushed a reworked version of this branch which

rewrites the commit history to be more easily reviewable (I hope),
fixes naming conventions,
fixes the uninitialized use of g_key,
ensures each implementation of the thread_local behavior only bumps the internal ID accumulator on the first SetInternalName per thread,
removes the unused GetInternalID function,
removes fallback inference from process name when thread name is unset, and explicitly names main threads (bitcoind, bitcoin-qt), and
fixes /* Continued */ logline behavior by introducing *Continued macros which don’t prefix log message with thread name.

jamesob force-pushed on May 5, 2018

jamesob force-pushed on May 6, 2018

jamesob commented at 8:21 pm on May 6, 2018: member

Pushed a small fix for a mysterious segfault which was happening on 2 x86_64 linux Travis jobs. Core dump and brief writeup in gist below. Build is now passing.

threadnames2.2 -> threadnames2.3

TheBlueMatt commented at 8:25 pm on May 6, 2018: member

What platforms still don’t have thread_local? Can we just ifdef everything and upgrade our release build OSX SDK and get it in every release platform?

On May 4, 2018 9:01:28 PM UTC, jamesob notifications@github.com wrote:

Replaces #13099.

The goal here is the same as the previous PR, but this approach uses @theuni’s gracefully degrading thread-local caching strategy to avoid (when possible) map lookup and mutex overhead during thread name lookup.

Instead of using a mutex-protected map to generate numeric suffixes (e.g. httpworker.2) we explicitly pass in suffixes during thread creation.

The logging format is also slightly different:
 0[bitcoind     ] 2018-05-04T20:58:13Z nBestHeight = 1296342
 1[torcontrol   ] 2018-05-04T20:58:13Z torcontrol thread start
 2[bitcoind     ] 2018-05-04T20:58:13Z Bound to [::]:18333
 3[bitcoind     ] 2018-05-04T20:58:13Z Bound to 0.0.0.0:18333
 4[bitcoind     ] 2018-05-04T20:58:13Z init message: Loading P2P
 5addresses...
 6[loadblk      ] 2018-05-04T20:58:13Z Leaving InitialBlockDownload
 7(latching to false)
 8[loadblk      ] 2018-05-04T20:58:13Z Imported mempool transactions from
 9disk: 3 succeeded, 0 failed, 0 expired, 0 already there
10[bitcoind     ] 2018-05-04T20:58:13Z Loaded 19762 addresses from
11peers.dat  102ms
12[bitcoind     ] 2018-05-04T20:58:13Z init message: Loading banlist...
13[bitcoind     ] 2018-05-04T20:58:13Z init message: Starting network
14threads...
15[net          ] 2018-05-04T20:58:13Z net thread start
16[addcon       ] 2018-05-04T20:58:13Z addcon thread start
17[dnsseed      ] 2018-05-04T20:58:13Z dnsseed thread start
18[msghand      ] 2018-05-04T20:58:13Z msghand thread start
19[bitcoind     ] 2018-05-04T20:58:13Z init message: Done loading
You can view, comment on, or merge this pull request online at:

#13168

– Commit Summary –

threads: add threadval files

threads: hook up threadval for logging

threads: add numeric suffixes to threads with the same name

tests: add threadutil naming tests

threads: add thread names to deadlock debugging tools

– File Changes –

M src/Makefile.am (2) M src/Makefile.test.include (1) M src/httpserver.cpp (11) M src/init.cpp (7) M src/logging.cpp (11) M src/sync.cpp (14) M src/test/test_bitcoin.cpp (2) A src/test/threadutil_tests.cpp (90) A src/threadutil.cpp (237) A src/threadutil.h (62) M src/util.cpp (21) M src/util.h (6) M src/validation.cpp (5) M src/validation.h (8)

– Patch Links –

https://github.com/bitcoin/bitcoin/pull/13168.patch https://github.com/bitcoin/bitcoin/pull/13168.diff

– You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/bitcoin/bitcoin/pull/13168

sipa commented at 9:35 pm on May 6, 2018: member

General comment: never @mention someone directly in a commit (just attribute them by name). They’ll be spammed by every fork on github when those commits are merged by them.

in src/threadutil.cpp:88 in 7db4e45b9d outdated

83+}
84+
85+void thread_util::Rename(std::string name)
86+{
87+    SetProcessName(name.c_str());
88+    SetInternalName(name);

sipa commented at 9:37 pm on May 6, 2018:

This can be SetInternalName(std::move(name)).

in src/threadutil.cpp:109 in 7db4e45b9d outdated

105+}
106+
107+bool thread_util::SetInternalName(std::string name)
108+{
109+    static std::atomic<long> id_accumulator{0};
110+    static thread_local thread_id{id_accumulator++};

sipa commented at 9:40 pm on May 6, 2018:

This increments id every time the name is set (regardless of whether it had a name already).

jamesob commented at 3:52 am on May 7, 2018:

Doesn’t the static thread_local attribute prevent that?

sipa commented at 4:29 am on May 7, 2018:

Oh, yes indeed. Ignore me

in src/threadutil.cpp:135 in 7db4e45b9d outdated

130+}
131+
132+static bool EnsureKeyCreated()
133+{
134+    static pthread_once_t key_once = PTHREAD_ONCE_INIT;
135+    return pthread_once(&key_once, make_key) ? false : true;

sipa commented at 9:42 pm on May 6, 2018:

Can be written as !pthread_once(&key_once, make_key);.

in src/sync.cpp:48 in e7a091d8a8 outdated

44     {
45         mutexName = pszName;
46         sourceFile = pszFile;
47         sourceLine = nLine;
48         fTry = fTryIn;
49+        thread_name = thread_name_;

sipa commented at 9:54 pm on May 6, 2018:

This can be written as thread_name = std::move(thread_name_) to avoid a copy.

sipa commented at 9:58 pm on May 6, 2018: member

Some more comments.

Overall: why do we need LogPrint*Continued? It should be implied by a lack of newline on the previous log statement (which is already used to determine whether to log the time).

jamesob commented at 3:54 am on May 7, 2018: member

We need LogPrint*Continued to prevent prefixing a line continuation with a thread name. Thanks for the look, will incorporate the feedback tomorrow.

jamesob force-pushed on May 7, 2018

jamesob commented at 2:08 pm on May 7, 2018: member

@sipa ah, sorry: I missed your point about the LogPrint macros. I see now that we can just move thread name attachment to reuse the existing m_started_new_line stuff, thanks. I’ve removed the last commit and worked in your other feedback.

jamesob/threadnames2.3 -> jamesob/threadnames2.4

jamesob commented at 2:12 pm on May 7, 2018: member

@TheBlueMatt honestly I’m not sure about the thread_local stuff; all I know is that mingw32 wasn’t behaving well with its use (as noted in the comment) - @theuni is the authority there.

in src/threadutil.cpp:26 in b891a44af4 outdated

19+ * mingw32's implementation of thread_local has also been shown to behave
20+ * erroneously under concurrent usage; see:
21+ *
22+ *   https://gist.github.com/jamesob/fe9a872051a88b2025b1aa37bfa98605
23+ */
24+#undef HAVE_THREAD_LOCAL

sipa commented at 3:31 pm on May 7, 2018:

I think this line may be unintentional.

jamesob commented at 3:42 pm on May 7, 2018:

I don’t think so - see the comment above; sounds like @theuni wants to do more testing with dynamic linking before we use thread_local outside the context of debug code.

sipa commented at 6:43 pm on May 7, 2018:

Unsure if we should have the code in in that case, as it’s untestable (it also doesn’t compile currently).

in src/threadutil.cpp:75 in b891a44af4 outdated

70+#if !defined(CAN_READ_PROCESS_NAME)
71+    return "";
72+#endif
73+
74+    char threadname_buff[16];
75+    char* pthreadname_buff = (char*)(&threadname_buff);

sipa commented at 3:33 pm on May 7, 2018:

I don’t think you need this variable; using threadname_buff will automatically decay to (char *).

jamesob force-pushed on May 7, 2018

jamesob commented at 5:05 pm on May 7, 2018: member

Changed with more feedback from @sipa.

jamesob/threadnames2.4 -> .5

theuni commented at 7:46 pm on May 7, 2018: member

@TheBlueMatt unfortunately it’s not the SDK, it’s Apple’s clang itself that had thread_local patched out until xcode 9.0, released in June 2017. And to make it worse, they held off on supporting it because they “didn’t want to commit to an inefficient abi”. It’s that reasoning that makes me believe that a build with an upstream clang may have compatibility issues with end-users’ libc/libstdc++. A few tests might shed some light, but even then, I’d worry about one-off version issues.

So, options are:

Move forward with thread_local, require mac builders to upgrade to xcode 9, hope for no abi issues
Wait for xcode 9 to be a reasonable minimum, same as above
#ifndef __APPLE__ …
No thread_local for now

Those options ignore mingw, with which @jamesob has also reported some thread_local issues, but I haven’t investigated those. @sipa I left the thread_local code but undef’d the variable in case we want to go for #3. Otherwise, I begrudgingly agree that it probably shouldn’t be present until it’s usable.

in src/threadutil.cpp:109 in 2d36119493 outdated

104+}
105+
106+bool thread_util::SetInternalName(std::string name)
107+{
108+    static std::atomic<long> id_accumulator{0};
109+    static thread_local thread_id{id_accumulator++};

sipa commented at 2:09 pm on May 8, 2018:

This declaration misses a type (when you uncomment the #undef HAVE_THREAD_LOCAL).

jamesob commented at 3:06 pm on May 8, 2018:

More evidence that we should remove this code until we need it. I’ll strip it out.

jamesob force-pushed on May 8, 2018

jamesob commented at 5:05 pm on May 8, 2018: member

I’ve pushed changes removing the unused thread_local implementation.

jamesob/threadnames2.5 -> .6

in src/validation.cpp:1707 in 6b12218a82 outdated

1650@@ -1650,8 +1651,8 @@ static bool WriteUndoDataForBlock(const CBlockUndo& blockundo, CValidationState&
1651 
1652 static CCheckQueue<CScriptCheck> scriptcheckqueue(128);
1653 
1654-void ThreadScriptCheck() {
1655-    RenameThread("bitcoin-scriptch");
1656+void ThreadScriptCheck(int worker_num) {
1657+    thread_util::Rename(("scriptch." + std::to_string(worker_num)).c_str());

sipa commented at 2:21 am on May 14, 2018:

Using thread_util::Rename(strprintf("scriptch.%i", worker_num)); would be simpler.

EDIT: also, std::to_string is locale-dependent so should probably be avoided.

jamesob commented at 2:19 pm on July 12, 2018:

Ah thanks, will fix the httpworker rename calls as well.

MarcoFalke commented at 4:30 pm on May 17, 2018: member

Needs rebase due to mege of #13236

jamesob commented at 6:07 pm on May 17, 2018: member

@TheBlueMatt and @ryanofsky gave feedback offline that we should only include a (very simple) thread_local implementation for this change, undef HAVE_THREAD_LOCAL on problematic platforms (e.g. Apple, Windows), and only include threadnames on supported platforms. Does anyone disagree with this? If not, I’ll implement that sometime in the next few days.

ryanofsky commented at 6:19 pm on May 17, 2018: member

@TheBlueMatt and @ryanofsky gave feedback offline that we should only include a (very simple) thread_local implementation for this change

I’m happy with either approach. I just wanted to suggest that not logging thread names on platforms that don’t support thread_local could be ok and simplify things.

jamesob force-pushed on May 21, 2018

jamesob commented at 4:36 pm on May 21, 2018: member

I’ve pushed a simplified rework of this branch which removes all non-thread_local implementations of the threadutil stuff; we just won’t support threadnames if the platform in question doesn’t support thread_local. I’ve also added a flag to disable threadname prefixes (-logthreadnames) a la -logtimestamps, and have added related release notes.

This should be ready for review. One outstanding question I have is where we should be doing the conditional #undef HAVE_THREAD_LOCAL – threadutil.cpp doesn’t seem like the right place.

jamesob force-pushed on May 21, 2018

jamesob referenced this in commit 2ed61a42f2 on May 21, 2018

jamesob force-pushed on May 21, 2018

skeees commented at 4:59 pm on May 24, 2018: contributor

concept ACK (I’m already finding this useful) - a quick note that this breaks combine logs.py (but trivial fix - just need to update the regexp that identifies timestamps)

MarcoFalke commented at 1:58 pm on May 30, 2018: member

Needs rebase due to merge of #13341

jamesob force-pushed on Jun 4, 2018

jamesob referenced this in commit 3e1de02c25 on Jun 4, 2018

jamesob force-pushed on Jun 5, 2018

jamesob commented at 6:45 pm on June 5, 2018: member

Thanks for the heads-up, @MarcoFalke. I’ve rebased and pushed a fix to combine_logs.py (thanks @skeees). This is ready for review-for-merge.

in src/util.cpp:12 in e645437403 outdated

 8@@ -9,6 +9,7 @@
 9 #include <random.h>
10 #include <serialize.h>
11 #include <utilstrencodings.h>
12+#include <threadutil.h>

skeees commented at 5:30 pm on June 6, 2018:

this include necessary?

jamesob commented at 7:05 pm on June 8, 2018:

I think so: thread_util::Rename is used on line 318.

jamesob commented at 4:16 pm on June 14, 2018:

Oh no, you’re right: I confused this with util.h. Thanks!

in src/util.h:321 in e645437403 outdated

309@@ -309,15 +310,12 @@ std::string HelpMessageOpt(const std::string& option, const std::string& message
310  */
311 int GetNumCores();
312 
313-void RenameThread(const char* name);
314-
315 /**
316  * .. and a wrapper that just calls func once
317  */
318 template <typename Callable> void TraceThread(const char* name,  Callable func)

skeees commented at 5:34 pm on June 6, 2018:

really feels like you should just lift this out into threadutil

jamesob commented at 7:09 pm on June 8, 2018:

Only problem is that’d create a circular dep with logging and threadutil due to use of LogPrintf here. I agree that in concept that’s where it should live, but it doesn’t look trivial to avoid that circular dep.

in configure.ac:790 in e645437403 outdated

769+        AC_MSG_RESULT(no)
770+        ;;
771+      *darwin*)
772+        AC_MSG_RESULT(no)
773+        ;;
774+      *)

skeees commented at 5:39 pm on June 6, 2018:

if you are that concerned about sane behavior for thread_local, does it make more sense to take a whitelist approach?

ryanofsky commented at 2:03 pm on June 13, 2018:

In commit “disable thread_local on unreliable platforms” (3e1de02c2500cd82ed4a112aa0198dc601d7947c)

if you are that concerned about sane behavior for thread_local, does it make more sense to take a whitelist approach?

IMO, blacklisting is an appropriate way to work around bugs in implementations of a standard API like thread_local. I think it would be overkill to assume going forward that every new platform providing thread_local has a buggy implementation just because implementations on two somewhat neglected platforms happened to have bugs at some point.

in src/threadutil.h:30 in e645437403 outdated

25+     * Rename a thread both in terms of an internal (in-memory) name as well
26+     * as its system process name.
27+     *
28+     * @return whether or not the rename succeeded.
29+     */
30+    void Rename(std::string);

skeees commented at 5:45 pm on June 6, 2018:

if this is the only setting function thats currently used outside of this translation unit, maybe make Set{Internal,Process}Name static so they arent exposed until theres a reason to have separate internal and internal names?

in src/threadutil.h:10 in e645437403 outdated

17+
18+#if (defined(PR_GET_NAME) || defined(MAC_OSX))
19+#define CAN_READ_PROCESS_NAME
20+#endif
21+
22+namespace thread_util

skeees commented at 5:46 pm on June 6, 2018:

I think you can add some consts to the functions declared here

in src/threadutil.cpp:36 in e645437403 outdated

31+}
32+
33+std::string thread_util::GetProcessName()
34+{
35+#if !defined(CAN_READ_PROCESS_NAME)
36+    return "";

skeees commented at 6:17 pm on June 6, 2018:

it feels weird that i can set it, but then cannot read it back. also this function isn’t used anywhere except tests so maybe just remove GetProcessName

in src/threadutil.cpp:79 in e645437403 outdated

74+}
75+
76+bool thread_util::SetInternalName(std::string name)
77+{
78+    static std::atomic<long> id_accumulator{0};
79+    static thread_local long thread_id{id_accumulator++};

skeees commented at 6:19 pm on June 6, 2018:

thread_id is never used for anything

ryanofsky commented at 3:20 pm on June 13, 2018:

In commit “tests: add threadutil tests” (b1982dd303f8994a9e5a14e2e3b0a3b1fe98da25)

thread_id is never used for anything`

I would also encourage you to drop thread_id. There are already a bunch of unique identifiers for threads: gettid(), pthread_self(), std::this_thread::get_id(), so I think it’d be good to have clear rationale before adding a new one.

jamesob commented at 2:40 pm on June 14, 2018:

Yep, dropped. The changeset has been substantially simplified to use a single thread_local std::string g_thread_name variable instead of a struct.

in src/logging.cpp:210 in e645437403 outdated

210+    if (!m_log_threadnames || !m_started_new_line) {
211+        return str;
212+    }
213+    std::string thread_name = thread_util::GetInternalName();
214+    // The longest thread name (with numeric suffix) we have at the moment is 13 characters.
215+    thread_name.resize(13, ' ');

skeees commented at 6:20 pm on June 6, 2018:

what happens if you name something longer? truncate? worth amending comment to specify

jamesob commented at 2:40 pm on June 14, 2018:

We’re now no longer resizing the internal threadname; thanks.

in src/sync.cpp:48 in e645437403 outdated

44     {
45         mutexName = pszName;
46         sourceFile = pszFile;
47         sourceLine = nLine;
48         fTry = fTryIn;
49+        thread_name = std::move(thread_name_);

skeees commented at 6:22 pm on June 6, 2018:

you do a move here but a copy into the function you probably want an rvalue ref and a forward - performance is probably reasonable to worry about here because i think this is called every time a lock is acquired? if you make thread_util::GetName() return a const then even better because all of this should get reused

ryanofsky commented at 4:33 pm on June 13, 2018:

In commit “threads: add thread names to deadlock debugging message” (2b75975636ed943b2a2678edde2a75e15af2c8bf)

you do a move here but a copy into the function you probably want an rvalue ref and a forward - performance is probably reasonable to worry about here because i think this is called every time a lock is acquired? if you make thread_util::GetName() return a const then even better because all of this should get reused

I don’t think this is right. Exactly one std::string move from the GetInternalName returned object to the CLockLocation::thread_name struct member should be required in either case. What might make this code slightly more efficient, though, would be to use the move constructor instead of the move operator=, by writing thread_name(std::move(thread_name_)) and avoiding default string initialization.

There would be a some noteable downsides if this code were changed to use rvalue references. If you changed it to take a std::string&& reference, it would be unnecessarily difficult to call with an lvalue expression, and if you changed it to take a T&& and use std::forward<T> it could unnecessarily bloat the executable with different template instantiations.

In general, when you write a function that inserts an object into a data structure, it is good to pass by value and use std::move instead of messing with rvalue references.

jamesob commented at 2:41 pm on June 14, 2018:

Took @ryanofsky’s advice and refactored this constructor to use an initialization list.

in src/logging.cpp:216 in e645437403 outdated

217+}
218+
219 void BCLog::Logger::LogPrintStr(const std::string &str)
220 {
221-    std::string strTimestamped = LogTimestampStr(str);
222+    std::string strPrefixed = LogThreadnameStr(LogTimestampStr(str));

jnewbery commented at 9:42 pm on June 6, 2018:

It seems more natural to me to have the thread name after the timestamp.

This way round breaks combine_logs without a fix. I imagine other log parsers expect the timestamp at the start of the line as well.

ryanofsky commented at 4:11 pm on June 13, 2018:

In commit “threads: prefix log messages with thread names” (d1385ab370b6100bd920ceb817688655b94c650e)

It seems more natural to me to have the thread name after the timestamp.

I’d agree with John. A timestamp seems like an inherent property of any logged event, while a thread name seems more like a piece of debug information might happen to be associated with some events. Also, if you are piping to sort, it seems more natural to sort based on timestamp than thread name.

jamesob commented at 2:38 pm on June 14, 2018:

Fixed

in src/threadutil.h:33 in e645437403 outdated

28+     * @return whether or not the rename succeeded.
29+     */
30+    void Rename(std::string);
31+
32+    /**
33+     * Set the thread's internal (in-memory) name; used e.g. for identification in

jnewbery commented at 5:33 pm on June 7, 2018:

Comment is incorrect. Should be Get the thread's ..., or @return the thread's...

jamesob commented at 2:41 pm on June 14, 2018:

Fixed.

in test/functional/combine_logs.py:16 in e645437403 outdated

11@@ -12,8 +12,8 @@
12 import re
13 import sys
14 
15-# Matches on the date format at the start of the log event
16-TIMESTAMP_PATTERN = re.compile(r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}Z")
17+# Matches on the date format or threadname prefix at the start of the log event
18+PREFIX_PATTERN = re.compile(r"^(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}Z|\[\w+\s*\] )")

jnewbery commented at 5:40 pm on June 7, 2018:

The pattern doesn’t work for the [httpworker.n ] thread logs:

0/tmp/user/1000/testb2liucdnnode0 [http         ] 2018-06-07T17:33:43.612724Z Received a POST request for / from 127.0.0.1:34830
1
2[httpworker.2 ] 2018-06-07T17:33:43.612865Z ThreadRPCServer method=getblockcount user=__cookie__ 
3 node0 [http         ] 2018-06-07T17:33:43.613814Z Received a POST request for / from 127.0.0.1:34830
4
5[httpworker.0 ] 2018-06-07T17:33:43.613905Z ThreadRPCServer method=listwallets user=__cookie__ 
6 node0 [http         ] 2018-06-07T17:33:43.614514Z Received a POST request for / from 127.0.0.1:34830

This problem goes away if you leave the timestamp at the start of the log string.

jnewbery commented at 5:40 pm on June 7, 2018: member

Generally looks good. A couple of comments inline.

the txindex thread is not named. I think you’ll need to call thread_util::Rename() in TxIndex::Start() (in txindex.cpp).

in configure.ac:788 in 3e1de02c25 outdated

767+        # erroneously under concurrent usage; see:
768+        # https://gist.github.com/jamesob/fe9a872051a88b2025b1aa37bfa98605
769+        AC_MSG_RESULT(no)
770+        ;;
771+      *darwin*)
772+        AC_MSG_RESULT(no)

ryanofsky commented at 2:17 pm on June 13, 2018:

In commit “disable thread_local on unreliable platforms” (3e1de02c2500cd82ed4a112aa0198dc601d7947c)

Could you add a comment here with a todo to enable thread_local for newer versions of darwin where it is supported? According to https://stackoverflow.com/questions/28094794/why-does-apple-clang-disallow-c11-thread-local-when-official-clang-supports/29929949#29929949, Apple announced support for thread_local in a developer presentation linked in that answer.

It should be possible in the future (no need to do it in this PR) to check for this support using an https://clang.llvm.org/docs/LanguageExtensions.html#c-11-thread-local autoconf check or another autoconf check.

jamesob commented at 2:32 pm on June 14, 2018:

Added, thanks.

in src/threadutil.cpp:18 in afce7f5ffc outdated

13+
14+#ifdef HAVE_SYS_PRCTL_H
15+#include <sys/prctl.h> // For prctl, PR_SET_NAME, PR_GET_NAME
16+#endif
17+
18+void thread_util::SetProcessName(const char* name)

ryanofsky commented at 2:49 pm on June 13, 2018:

In commit “threads: introduce threadutil, move RenameProcess, add thread suffixes” (afce7f5ffce546c4d1aa5111ea02bf9a671cc775)

This should be called SetThreadName, not SetProcessName (similarly for GetProcessName) below. The pthread calls obviously affect the thread rather than the process, and from http://man7.org/linux/man-pages/man2/prctl.2.html, the prctl call will “set the name of the calling thread”.

jamesob commented at 2:33 pm on June 14, 2018:

Fixed

in src/httpserver.cpp:284 in afce7f5ffc outdated

281@@ -281,7 +282,7 @@ static void http_reject_request_cb(struct evhttp_request* req, void*)
282 /** Event dispatcher thread */
283 static bool ThreadHTTP(struct event_base* base, struct evhttp* http)
284 {
285-    RenameThread("bitcoin-http");

ryanofsky commented at 2:55 pm on June 13, 2018:

In commit “threads: introduce threadutil, move RenameProcess, add thread suffixes” (afce7f5ffce546c4d1aa5111ea02bf9a671cc775)

I think the reason for the bitcoin- prefix is that it makes it easier to distinguish bitcoin threads from other process threads if you press H in top, though I’m sure there are other ways to accomplish this.

Maybe call SetProcessName with the bitcoin- prefix and SetInternalName without it?

jamesob commented at 2:33 pm on June 14, 2018:

Took your advice; am now prefixing threadname with "bitcoin-" for SetThreadName calls.

in src/threadutil.cpp:61 in afce7f5ffc outdated

56+ * If we have thread_local, just keep thread ID and name in a thread_local
57+ * global.
58+ */
59+#if defined(HAVE_THREAD_LOCAL)
60+
61+struct thread_data_type

ryanofsky commented at 3:11 pm on June 13, 2018:

In commit “threads: introduce threadutil, move RenameProcess, add thread suffixes” (afce7f5ffce546c4d1aa5111ea02bf9a671cc775)

Name of this struct seems unusual. I’d probably call it to something like ThreadName or ThreadData, but I think you should keep whatever name you prefer.

jamesob commented at 2:34 pm on June 14, 2018:

thread_data_type has been removed entirely.

in src/threadutil.cpp:63 in afce7f5ffc outdated

58+ */
59+#if defined(HAVE_THREAD_LOCAL)
60+
61+struct thread_data_type
62+{
63+    constexpr thread_data_type() = default;

ryanofsky commented at 3:16 pm on June 13, 2018:

In commit “threads: introduce threadutil, move RenameProcess, add thread suffixes” (afce7f5ffce546c4d1aa5111ea02bf9a671cc775)

Does constexpr here actually do anything? I’m suprised the compiler even allows it with the std::string struct member.

jamesob commented at 2:38 pm on June 14, 2018:

Fixed; thread_data_type has been removed.

in src/httpserver.cpp:334 in afce7f5ffc outdated

328@@ -328,9 +329,9 @@ static bool HTTPBindAddresses(struct evhttp* http)
329 }
330 
331 /** Simple wrapper to set thread name and run work queue */
332-static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue)
333+static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue, int worker_num)
334 {
335-    RenameThread("bitcoin-httpworker");
336+    thread_util::Rename(("httpworker." + std::to_string(worker_num)).c_str());

ryanofsky commented at 3:24 pm on June 13, 2018:

In commit “threads: introduce threadutil, move RenameProcess, add thread suffixes” (afce7f5ffce546c4d1aa5111ea02bf9a671cc775)

This commit is kind of a hodgepodge. Maybe split it into separate commits that just do one thing (move the rename api, change the thread names, add new thread local data).

jamesob commented at 2:44 pm on June 14, 2018:

This commit seems tough to split up in a meaningful way. Hopefully the reduced size of the threadutil change (now that we aren’t doing anything with a generic thread data struct) makes it easier to review, but it’ll take a lot of rework to stage the changes out as you suggest. I’m happy to do this if you think it’s worthwhile, but wanted to check before doing so to see if the simplifications make a difference for this recommendation.

in src/test/threadutil_tests.cpp:21 in b1982dd303 outdated

16+
17+#include <boost/test/unit_test.hpp>
18+
19+BOOST_FIXTURE_TEST_SUITE(threadutil_tests, BasicTestingSetup)
20+
21+BOOST_AUTO_TEST_CASE(threadutil_test_process_rename_serial)

ryanofsky commented at 3:40 pm on June 13, 2018:

In commit “tests: add threadutil tests” (b1982dd303f8994a9e5a14e2e3b0a3b1fe98da25)

Maybe note in a comment that this will overwrite and clear the test thread name on platforms that don’t support CAN_READ_PROCESS_NAME, since this may affect later tests, and display in task managers.

jamesob commented at 2:45 pm on June 14, 2018:

Removed this test.

in doc/release-notes-pr13168.md:4 in d1385ab370 outdated

0@@ -0,0 +1,5 @@
1+Thread names in logs
2+--------------------
3+
4+Log lines are now prefixed by default with the name of the thread that caused

ryanofsky commented at 3:44 pm on June 13, 2018:

In commit “threads: prefix log messages with thread names” (d1385ab370b6100bd920ceb817688655b94c650e)

Probably should prefix this with, “On platforms that support it…”

jamesob commented at 2:45 pm on June 14, 2018:

Fixed, thanks.

in src/init.cpp:460 in d1385ab370 outdated

456@@ -457,6 +457,7 @@ void SetupServerArgs()
457     gArgs.AddArg("-help-debug", "Show all debugging options (usage: --help -help-debug)", false, OptionsCategory::DEBUG_TEST);
458     gArgs.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), false, OptionsCategory::DEBUG_TEST);
459     gArgs.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), false, OptionsCategory::DEBUG_TEST);
460+    gArgs.AddArg("-logthreadnames", strprintf("Prepend debug output with name of the originating thread (default: %u)", DEFAULT_LOGTHREADNAMES), false, OptionsCategory::DEBUG_TEST);

ryanofsky commented at 3:44 pm on June 13, 2018:

In commit “threads: prefix log messages with thread names” (d1385ab370b6100bd920ceb817688655b94c650e)

Documentation should note that this feature isn’t supported on all platforms, causing the thread name column to appear empty.

jamesob commented at 2:34 pm on June 14, 2018:

Fixed

in src/logging.cpp:203 in d1385ab370 outdated

203-        m_started_new_line = false;
204-
205     return strStamped;
206 }
207 
208+std::string BCLog::Logger::LogThreadnameStr(const std::string &str)

ryanofsky commented at 3:58 pm on June 13, 2018:

In commit “threads: prefix log messages with thread names” (d1385ab370b6100bd920ceb817688655b94c650e)

Changing the const std::string &str declaration to std::string str here would avoid an unnecessary string copy in the case where str is returned directly (it would be moved from instead of copied, see https://en.cppreference.com/w/cpp/language/return). The same optimization is also applicable to LogTimestampStr above.

jamesob commented at 2:37 pm on June 14, 2018:

Now that we’ve reversed the order of threadname and log timestamp (threadname follows timestamp), I’ve only modified LogTimestampStr per your suggestion since it’s the only function of the two to receive an rvalue as input. LogThreadnameStr receives an lvalue from LogPrintStr which itself receives an lvalue from logging.h:LogPrintf; I may be mistaken here, but the optimization you describe wouldn’t apply in this case.

in src/qt/bitcoin.cpp:286 in 56deb18c8b outdated

282@@ -282,6 +283,7 @@ void BitcoinCore::initialize()
283     try
284     {
285         qDebug() << __func__ << ": Running initialization in thread";
286+        thread_util::Rename("bitcoin-qt");

ryanofsky commented at 5:12 pm on June 13, 2018:

In commit “threads: explicitly name main threads” (56deb18c8bc36de5bb49c7b1db27adfa80ce7169)

This is giving 2 different threads (the main() thread, and the initialization thread spawned in BitcoinApplication::startThread) the same name. It might be better to distinguish this thread by calling it qt-init or something instead of bitcoin-qt.

This is also kind of an awkward place to be name the thread, since it isn’t in a standard thread entry point or close to where the thread is created. Maybe it would make sense for us to have a custom QThread subclass that supports named threads, and calls thread_util::Rename in exec(). Or maybe we could have write a little helper object that attaches to a QThread, listens for the started signal, and sets the thread name in the signal handler.

jamesob commented at 2:46 pm on June 14, 2018:

Changed the name of this thread to bitcoin-qt-init.

Agree with you that this is an awkward spot for naming. Do you think your proposed fix should be done along with this changeset or maybe as a follow-up PR?

ryanofsky commented at 9:12 pm on June 19, 2018:

#13168 (review)

Do you think your proposed fix should be done along with this changeset or maybe as a follow-up PR?

I might opt to do it in a different PR because QThread is also used in rpcconsole.cpp and bitcoin.cpp, and it might make sense to update those places to set thread names in the same way. But I don’t have a real opinion. It seems fine to make the change in this PR, in another PR, or not at all.

ryanofsky commented at 5:32 pm on June 13, 2018: member

utACK e6454374033760d93a33619bea1451573718dd3d

jamesob force-pushed on Jun 13, 2018

jamesob referenced this in commit 789758c500 on Jun 13, 2018

jamesob force-pushed on Jun 13, 2018

jamesob referenced this in commit b4c026b739 on Jun 13, 2018

jamesob force-pushed on Jun 14, 2018

jamesob referenced this in commit cdada4f684 on Jun 14, 2018

jamesob commented at 2:50 pm on June 14, 2018: member

Thanks very much for the reviews, @skeees @jnewbery @ryanofsky. I’ve rebased and pushed changes incorporating your good feedback. The changeset has been simplified; instead of the generic thread data struct (which was more or less a vestige from when we were trying to provide threadnames for all platforms, even those not supporting thread_local), we’re now just using a single thread_local variable for the threadname. I’ve also moved the threadname back to following timestamp as suggested.

jamesob commented at 2:54 pm on June 14, 2018: member

Looks like I botched the rebase; https://github.com/bitcoin/bitcoin/pull/13168/commits/d930487b3dc398f3ac93c00324fff027a4c61588 shouldn’t be in this PR… Fixing.

jamesob force-pushed on Jun 14, 2018

jamesob referenced this in commit bf2cb44e5b on Jun 14, 2018

jamesob commented at 3:24 pm on June 14, 2018: member

Botched rebase fixed.

jamesob force-pushed on Jun 14, 2018

jamesob referenced this in commit 4c21846ec3 on Jun 14, 2018

jamesob force-pushed on Jun 15, 2018

jamesob referenced this in commit 696bdb7510 on Jun 15, 2018

in configure.ac:774 in 696bdb7510 outdated

771+        # erroneously under concurrent usage; see:
772+        # https://gist.github.com/jamesob/fe9a872051a88b2025b1aa37bfa98605
773+        AC_MSG_RESULT(no)
774+        ;;
775+      *darwin*)
776+        # TODO enable therad_local on later versions of Darwin where it is

ryanofsky commented at 9:24 pm on June 19, 2018:

In commit “disable thread_local on unreliable platforms” (696bdb751055c01c645dc95df486d56a873325de)

Little spelling mistake

jamesob commented at 3:35 pm on June 20, 2018:

D’oh. Fixed.

in src/bitcoind.cpp:61 in cf82eda8ae outdated

57@@ -57,6 +58,8 @@ static bool AppInit(int argc, char* argv[])
58 {
59     bool fRet = false;
60 
61+    thread_util::Rename("bitcoind");

ryanofsky commented at 9:36 pm on June 19, 2018:

In commit “threads: explicitly name main threads” (cf82eda8aec147a0d24ade9263f8df0708ff02bb)

Since OS thread names are now prefixed with “bitcoin-”, I guess these will show up as “bitcoin-bitcoind”, “bitcoin-bitcoin-qt-init”, and ““bitcoin-bitcoin-qt” in top? This seems ok, but a little redundant. You could consider just calling Rename() with “main” and “init” so the OS names would be “bitcoin-main” and “bitcoin-init”.

jamesob commented at 3:40 pm on June 20, 2018:

Done, thanks. Non-internal thread names now look like

 0 $ pstree 12441
 1
 2bitcoin-init─┬─{bitcoin-addcon}
 3             ├─{bitcoin-dnsseed}
 4             ├─4*[{bitcoin-httpwor}]
 5             ├─{bitcoin-http}
 6             ├─{bitcoin-init}
 7             ├─{bitcoin-loadblk}
 8             ├─{bitcoin-msghand}
 9             ├─{bitcoin-net}
10             ├─{bitcoin-opencon}
11             ├─{bitcoin-schedul}
12             ├─7*[{bitcoin-scriptc}]
13             └─{bitcoin-torcont}

ryanofsky commented at 9:38 pm on June 19, 2018: member

utACK cf82eda8aec147a0d24ade9263f8df0708ff02bb. Lots of little changes since the last review, all discussed above. Main user visible changes are putting thread names after timestamps on log lines and not padding log thread names with spaces.

jamesob force-pushed on Jun 20, 2018

jamesob referenced this in commit 6f854f68bc on Jun 20, 2018

jamesob commented at 3:41 pm on June 20, 2018: member

Thanks for the continued review, @ryanofsky. Pushed a few small changes addressing your feedback.

 0 $ git diff threadnames2.12..threadnames2.11 | cat
 1
 2diff --git a/configure.ac b/configure.ac
 3index 6873326..31c8c66 100644
 4--- a/configure.ac
 5+++ b/configure.ac
 6@@ -771,7 +771,7 @@ AC_LINK_IFELSE([AC_LANG_SOURCE([
 7         AC_MSG_RESULT(no)
 8         ;;
 9       *darwin*)
10-        # TODO enable thread_local on later versions of Darwin where it is
11+        # TODO enable therad_local on later versions of Darwin where it is
12         # supported (per https://stackoverflow.com/a/29929949)
13         AC_MSG_RESULT(no)
14         ;;
15diff --git a/src/bitcoind.cpp b/src/bitcoind.cpp
16index ee99099..066e83d 100644
17--- a/src/bitcoind.cpp
18+++ b/src/bitcoind.cpp
19@@ -58,7 +58,7 @@ static bool AppInit(int argc, char* argv[])
20 {
21     bool fRet = false;
22
23-    thread_util::Rename("init");
24+    thread_util::Rename("bitcoind");
25
26     //
27     // Parameters

jamesob force-pushed on Jun 20, 2018

jamesob commented at 4:28 pm on June 20, 2018: member

Oops – missed the QT Rename calls in the last change. Pushed:

 0 $ git diff threadnames2.12..threadnames2.13 | cat
 1
 2diff --git a/src/qt/bitcoin.cpp b/src/qt/bitcoin.cpp
 3index d3f97f7..f13e655 100644
 4--- a/src/qt/bitcoin.cpp
 5+++ b/src/qt/bitcoin.cpp
 6@@ -283,7 +283,7 @@ void BitcoinCore::initialize()
 7     try
 8     {
 9         qDebug() << __func__ << ": Running initialization in thread";
10-        thread_util::Rename("bitcoin-qt-init");
11+        thread_util::Rename("qt-init");
12         bool rv = m_node.appInitMain();
13         Q_EMIT initializeResult(rv);
14     } catch (const std::exception& e) {
15@@ -568,7 +568,7 @@ static void SetupUIArgs()
16 int main(int argc, char *argv[])
17 {
18     SetupEnvironment();
19-    thread_util::Rename("bitcoin-qt");
20+    thread_util::Rename("main");
21
22     std::unique_ptr<interfaces::Node> node = interfaces::MakeNode();

in src/threadutil.h:16 in d404d64abc outdated

11+{
12+    /**
13+     * Rename a thread both in terms of an internal (in-memory) name as well
14+     * as its system thread name.
15+     *
16+     * @return whether or not the rename succeeded.

jnewbery commented at 6:21 pm on June 20, 2018:

Nope. Return type is void.

in src/threadutil.cpp:53 in d404d64abc outdated

48+
49+/**
50+ * Set the in-memory internal name for this thread. Does not affect the process
51+ * name.
52+ */
53+static bool SetInternalName(const std::string& name)

jnewbery commented at 6:22 pm on June 20, 2018:

the returned bool isn’t used. Change to void (same for other definition of SetInternalName() below).

jnewbery commented at 6:25 pm on June 20, 2018:

In fact, since the #else definition here is doing nothing, I’d just remove these static functions entirely and add the following to Rename():

0#if defined(HAVE_THREAD_LOCAL)
1    g_thread_name = name;
2#endif

jamesob commented at 8:17 pm on June 22, 2018:

g_thread_name doesn’t exist as a symbol in non-thread_local enabled environments, so basically our choice is one #if defined(...) or three inline. I figure one is preferable, but if you feel strongly I’m happy to change.

jnewbery commented at 3:06 pm on June 25, 2018:

No, I don’t feel strongly. Both are fine!

in src/logging.cpp:176 in d404d64abc outdated

173@@ -168,7 +174,7 @@ std::vector<CLogCategoryActive> ListActiveLogCategories()
174     return ret;
175 }
176 
177-std::string BCLog::Logger::LogTimestampStr(const std::string &str)
178+std::string BCLog::Logger::LogTimestampStr(std::string str)

jnewbery commented at 7:16 pm on June 20, 2018:

I don’t think you need to change the signature here. Any reason to change from a const reference?

jamesob commented at 8:19 pm on June 22, 2018:

See #13168 (review)

jnewbery commented at 7:17 pm on June 20, 2018: member

A few nits inline.

The txindex thread is not named. Perhaps you lost that when rebasing on #13243

I’ve tested and other than those nits, it looks good!

jamesob force-pushed on Jun 22, 2018

jamesob commented at 8:44 pm on June 22, 2018: member

Thanks for the look, @jnewbery. Pushed threadnames2.13 -> threadnames2.14.

It turns out the txindex thread is actually named (here - GetName() is passed into TraceThread(), which then calls Rename()):

02018-06-22T20:36:46Z [txindex] txindex thread start
12018-06-22T20:36:46Z [qt-init] init message: Loading wallet...
22018-06-22T20:36:46Z [txindex] txindex is enabled
32018-06-22T20:36:46Z [txindex] txindex thread exit

jnewbery commented at 2:21 pm on June 25, 2018: member

Do you know what thread these leveldb logs come from:

 02018-06-25T14:20:09Z [init] Bitcoin Core version v0.16.99.0-unk (release build)
 12018-06-25T14:20:09Z [init] InitParameterInteraction: parameter interaction: -whitelistforcerelay=1 -> setting -whitelistrelay=1
 22018-06-25T14:20:09Z [init] Assuming ancestors of block 0000000000000000005214481d2d96f898e3d5416e43359c145944a909d242e0 have valid signatures.
 32018-06-25T14:20:09Z [init] Setting nMinimumChainWork=000000000000000000000000000000000000000000f91c579d57cad4bc5278cc
 42018-06-25T14:20:09Z [init] Using the 'sse4(1way+4way)' SHA256 implementation
 52018-06-25T14:20:09Z [init] Using RdRand as an additional entropy source
 62018-06-25T14:20:09Z [init] Default data directory /home/ubuntu/.bitcoin
 72018-06-25T14:20:09Z [init] Using data directory /home/ubuntu/.bitcoin
 82018-06-25T14:20:09Z [init] Using config file /home/ubuntu/.bitcoin/bitcoin.conf
 92018-06-25T14:20:09Z [init] Using at most 125 automatic connections (1024 file descriptors available)
102018-06-25T14:20:09Z [init] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
112018-06-25T14:20:09Z [init] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
122018-06-25T14:20:09Z [init] Using 2 threads for script verification
132018-06-25T14:20:09Z [init] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 127.0.0.1/32 
142018-06-25T14:20:09Z [init] Binding RPC on address :: port 44553
152018-06-25T14:20:09Z [init] Binding RPC on address 0.0.0.0 port 44553
162018-06-25T14:20:09Z [init] Binding RPC on address 0.0.0.0 port 44553 failed.
172018-06-25T14:20:09Z [init] Initialized HTTP server
182018-06-25T14:20:09Z [init] HTTP: creating work queue of depth 16
192018-06-25T14:20:09Z [init] Starting RPC
202018-06-25T14:20:09Z [init] Starting HTTP RPC server
212018-06-25T14:20:09Z [init] Config options rpcuser and rpcpassword will soon be deprecated. Locally-run instances may remove rpcuser to use cookie-based auth, or may be replaced with rpcauth. Please see share/rpcuser for rpcauth auth generation.
222018-06-25T14:20:09Z [init] Registering HTTP handler for / (exactmatch 1)
232018-06-25T14:20:09Z [init] Registering HTTP handler for /wallet/ (exactmatch 0)
242018-06-25T14:20:09Z [init] Starting HTTP server
252018-06-25T14:20:09Z [init] HTTP: starting 4 worker threads
262018-06-25T14:20:09Z [init] Using wallet directory /home/ubuntu/.bitcoin
272018-06-25T14:20:09Z [init] init message: Verifying wallet(s)...
282018-06-25T14:20:09Z [init] Using BerkeleyDB version Berkeley DB 4.8.30: (April  9, 2010)
292018-06-25T14:20:09Z [init] Using wallet wallet.dat
302018-06-25T14:20:09Z [init] BerkeleyEnvironment::Open: LogDir=/home/ubuntu/.bitcoin/database ErrorFile=/home/ubuntu/.bitcoin/db.log
312018-06-25T14:20:09Z [scheduler] scheduler thread start
322018-06-25T14:20:09Z [http] Entering http event loop
332018-06-25T14:20:09Z [init] net: setting try another outbound peer=false
342018-06-25T14:20:09Z [init] Cache configuration:
352018-06-25T14:20:09Z [init] * Using 2.0MiB for block index database
362018-06-25T14:20:09Z [init] * Using 56.0MiB for transaction index database
372018-06-25T14:20:09Z [init] * Using 8.0MiB for chain state database
382018-06-25T14:20:09Z [init] * Using 384.0MiB for in-memory UTXO set (plus up to 286.1MiB of unused mempool space)
392018-06-25T14:20:09Z [init] init message: Loading block index...
402018-06-25T14:20:09Z [init] LevelDB using max_open_files=1000 (default=1000)
412018-06-25T14:20:09Z [init] Opening LevelDB in /home/ubuntu/.bitcoin/blocks/index
422018-06-25T14:20:09Z [init] leveldb: Recovering log [#247](/bitcoin-bitcoin/247/)
432018-06-25T14:20:10Z [init] leveldb: Level-0 table [#249](/bitcoin-bitcoin/249/): started
442018-06-25T14:20:10Z [init] leveldb: Level-0 table [#249](/bitcoin-bitcoin/249/): 5789826 bytes OK
452018-06-25T14:20:10Z [init] leveldb: Recovering log [#248](/bitcoin-bitcoin/248/)
462018-06-25T14:20:10Z [init] leveldb: Level-0 table [#250](/bitcoin-bitcoin/250/): started
472018-06-25T14:20:10Z [init] leveldb: Level-0 table [#250](/bitcoin-bitcoin/250/): 193 bytes OK
482018-06-25T14:20:10Z [init] leveldb: Delete type=0 [#247](/bitcoin-bitcoin/247/)
492018-06-25T14:20:10Z [init] leveldb: Delete type=3 [#244](/bitcoin-bitcoin/244/)
502018-06-25T14:20:10Z [init] leveldb: Delete type=0 [#248](/bitcoin-bitcoin/248/)
512018-06-25T14:20:10Z [init] Opened LevelDB successfully
522018-06-25T14:20:10Z [init] Using obfuscation key for /home/ubuntu/.bitcoin/blocks/index: 0000000000000000
532018-06-25T14:20:10Z [] leveldb: Compacting 4@0 + 7@1 files
542018-06-25T14:20:10Z [] leveldb: Generated table [#252](/bitcoin-bitcoin/252/)@0: 15702 keys, 2141621 bytes
552018-06-25T14:20:10Z [] leveldb: Generated table [#253](/bitcoin-bitcoin/253/)@0: 8086 keys, 1117181 bytes
562018-06-25T14:20:10Z [] leveldb: Generated table [#254](/bitcoin-bitcoin/254/)@0: 15629 keys, 2139993 bytes
572018-06-25T14:20:10Z [] leveldb: Generated table [#255](/bitcoin-bitcoin/255/)@0: 6885 keys, 942686 bytes
582018-06-25T14:20:10Z [] leveldb: Generated table [#256](/bitcoin-bitcoin/256/)@0: 15662 keys, 2141826 bytes
592018-06-25T14:20:10Z [] leveldb: Generated table [#257](/bitcoin-bitcoin/257/)@0: 5521 keys, 755359 bytes
602018-06-25T14:20:10Z [] leveldb: Generated table [#258](/bitcoin-bitcoin/258/)@0: 5260 keys, 711244 bytes
612018-06-25T14:20:10Z [] leveldb: Compacted 4@0 + 7@1 files => 9949910 bytes
622018-06-25T14:20:10Z [] leveldb: compacted to: files[ 0 7 35 0 0 0 0 ]

jnewbery commented at 3:13 pm on June 25, 2018: member

Tested ACK 18928a194fa351e07eb808eaea01792ceb1d2093, modulo the question above about the leveldb logs.

If there are any further changes to this PR, I’d suggest squashing commit threads: explicitly name main threads into commit threads: introduce threadutil, refactor thread naming.

jamesob commented at 4:24 pm on June 25, 2018: member

@jnewbery Thanks for the follow-up. Turns out that the blank names contained in your logs come from a compaction thread started from within the leveldb source tree, so I don’t think there’s much we can do there.

I’ll be sure to squash the commits you reference pending more modifications.

ryanofsky commented at 11:27 am on July 4, 2018: member

utACK 18928a194fa351e07eb808eaea01792ceb1d2093. Only minor changes since last review: updating init thread names, dropping bool return values, fixing spelling mistake.

DrahtBot added the label Needs rebase on Jul 7, 2018

disable thread_local on unreliable platforms

See discussions here:

- https://github.com/bitcoin/bitcoin/pull/11722#pullrequestreview-79322658
- https://github.com/bitcoin/bitcoin/pull/13168#issuecomment-387181155

99d6a1e865

jamesob force-pushed on Jul 11, 2018

jamesob commented at 9:07 pm on July 11, 2018: member

Rebased

in src/logging.cpp:8 in 5ac8b41115 outdated

4@@ -5,6 +5,12 @@
5 
6 #include <logging.h>
7 #include <utiltime.h>
8+#include <util.h>

sipa commented at 11:24 pm on July 11, 2018:

What does logging need util for?

jamesob commented at 2:18 pm on July 12, 2018:

Good catch; this was a relic from previous code.

DrahtBot removed the label Needs rebase on Jul 12, 2018

threads: introduce threadutil, refactor thread naming

This work is prerequisite to attaching thread names to log lines and deadlock
debug utilities. threadutil allows setting of an "internal" threadname per
thread on platforms where thread_local is available.

This commit also moves RenameThread() out of util and adds a numeric suffix to
disambiguate between threads with the same name. It explicitly names a few
main threads using the new Rename() utility.

6e12f01b84

tests: add threadutil tests 002a570b5d

threads: prefix log messages with thread names

Introduce a new flag (`-logthreadnames`) which allows toggling
of this behavior.

577ffd40a0

threads: add thread names to deadlock debugging message

Also refactor CLockLocation to use an initialization list.

91aef702c9

jamesob force-pushed on Jul 12, 2018

jamesob commented at 2:31 pm on July 12, 2018: member

Thanks for the look, @sipa. I’ve incorporated your suggestions and squashed commits as suggested by @jnewbery earlier.

Diff here: threadnames2.15 -> .16

jnewbery commented at 10:02 pm on July 23, 2018: member

Tested ACK 91aef702c90d53c8f8dd53dfacb5d5f3d0cb2b91

jamesob referenced this in commit 558f3235ee on Aug 20, 2018

jamesob commented at 9:21 pm on August 20, 2018: member

I benchmarked this branch (as rebased on top of master) with bitcoinperf and it’s worth noting that we see a roughly 1.4% slowdown over master (details here) during IBD up to height 200,000.

ryanofsky commented at 4:05 pm on August 24, 2018: member

we see a roughly 1.4% slowdown over master

What’s the implication of this? Do you want to to try to optimize the change, or abandon it, or turn it off by default? Does the slowdown even happen in the default configuration, or only when extra debugging is enabled?

tACK 91aef702c90d53c8f8dd53dfacb5d5f3d0cb2b91. I just ran bitcoind -regtest and looked at ps thread names and log output. Only changes since my previous review were a rebase and tweaked thread names.

jamesob commented at 4:17 pm on August 24, 2018: member

@ryanofsky thanks for the look. I think given the observed slowdown, maybe disabling by default is the way to go. I don’t see any obvious means of improving performance, though I haven’t taken to profiling tools.

DrahtBot commented at 3:56 pm on August 31, 2018: member

DrahtBot added the label Needs rebase on Aug 31, 2018

DrahtBot added the label Up for grabs on Dec 3, 2018

DrahtBot commented at 4:08 pm on December 3, 2018: member

DrahtBot closed this on Dec 3, 2018

jamesob referenced this in commit 315d84314a on Jan 17, 2019

jamesob referenced this in commit 7550fc1bcc on Apr 18, 2019

jamesob referenced this in commit c1d159999c on Apr 18, 2019

jamesob referenced this in commit 188ca75e5f on Apr 26, 2019

pull[bot] referenced this in commit 2c35fe6238 on Apr 30, 2019

sidhujag referenced this in commit 500e70c86d on May 1, 2019

HashUnlimited referenced this in commit ddcb2ca45d on Aug 30, 2019

laanwj removed the label Needs rebase on Oct 24, 2019

barrystyle referenced this in commit e98602b60d on Nov 11, 2019

fanquake removed the label Up for grabs on Apr 7, 2021

fanquake commented at 6:37 am on April 7, 2021: member

Removing “Up for grabs” given #15849.

DrahtBot locked this on Aug 16, 2022

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