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

8722e54e56 threads: add thread names to deadlock debugging message (James O'Beirne)
383b186c28 threads: prefix log messages with thread names (James O'Beirne)
ddd95ccb80 tests: add threadutil tests (James O'Beirne)
ae5f2b6a6c threads: introduce util/threadnames, refactor thread naming (James O'Beirne)
188ca75e5f disable HAVE_THREAD_LOCAL on unreliable platforms (James O'Beirne)

Pull request description:

  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 |
  ```

ACKs for commit 8722e5:
  Empact:
    utACK 8722e54e56
  jnewbery:
    utACK 8722e54e56
  MarcoFalke:
    re-utACK 8722e54e56 (Only change since my previous review is DEFAULT_LOGTHREADNAMES=false and stylistic updates

Tree-SHA512: 50af992708295b8d680cf10025262dd964e599a356bdfc1dfc84fb18c00afabcb34d3d12d551b0677ff81f8fccad0e17c1d5b24dfecb953a913bc77fdd1a4577
This commit is contained in:
MarcoFalke
2019-04-30 15:24:45 -04:00
19 changed files with 239 additions and 58 deletions

View File

@@ -41,6 +41,7 @@
#include <script/sigcache.h>
#include <scheduler.h>
#include <shutdown.h>
#include <util/threadnames.h>
#include <timedata.h>
#include <txdb.h>
#include <txmempool.h>
@@ -206,7 +207,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();
@@ -506,6 +507,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);
@@ -666,7 +668,7 @@ static void CleanupBlockRevFiles()
static void ThreadImport(std::vector<fs::path> vImportFiles)
{
const CChainParams& chainparams = Params();
RenameThread("bitcoin-loadblk");
util::ThreadRename("loadblk");
ScheduleBatchPriority();
{
@@ -862,6 +864,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);
@@ -1286,7 +1289,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