This was always an on/off issue but to me it seems to have become worse a while ago.
It used to happen primarily when there was a backlog of unprocessed blocks that it had to validate at startup, catching up. E.g. if you checked the log there was a long list of:
02021-03-13T06:47:29Z UpdateTip: new best=000000000000000000027a13c5ca5988c608a05fe1dd19c6f28210926a767546 height=674028 version=0x3fff0000 log2_work=92.725597 tx=623551846 date='2021-03-10T16:20:36Z' progress=0.998736 cache=2.0MiB(14678txo)
However it happens every time now. It is worse with a wallet with a large number of transactions. Does it take the lock for every individual one?
I attached a debugger. The UI thread is indeed stuck waiting at a lock:
0(gdb) bt
1[#0](/bitcoin-core-gui/0/) __lll_lock_wait (futex=futex@entry=0x55b749266208 <cs_main>, private=0) at lowlevellock.c:52
2[#1](/bitcoin-core-gui/1/) 0x00007f2cccb9c131 in __GI___pthread_mutex_lock (mutex=0x55b749266208 <cs_main>) at ../nptl/pthread_mutex_lock.c:115
3[#2](/bitcoin-core-gui/2/) 0x000055b7486c264f in __gthread_mutex_lock(pthread_mutex_t*) (__mutex=0x55b749266208 <cs_main>) at /usr/lib/gcc/x86_64-linux-gnu/9/../../../../include/x86_64-linux-gnu/c++/9/bits/gthr-default.h:749
4[#3](/bitcoin-core-gui/3/) __gthread_recursive_mutex_lock(pthread_mutex_t*) (__mutex=0x55b749266208 <cs_main>) at /usr/lib/gcc/x86_64-linux-gnu/9/../../../../include/x86_64-linux-gnu/c++/9/bits/gthr-default.h:811
5[#4](/bitcoin-core-gui/4/) std::recursive_mutex::lock() (this=0x55b749266208 <cs_main>) at /usr/lib/gcc/x86_64-linux-gnu/9/../../../../include/c++/9/mutex:106
6[#5](/bitcoin-core-gui/5/) std::unique_lock<std::recursive_mutex>::lock() (this=0x7ffe0a15b018) at /usr/lib/gcc/x86_64-linux-gnu/9/../../../../include/c++/9/bits/unique_lock.h:141
7[#6](/bitcoin-core-gui/6/) UniqueLock<AnnotatedMixin<std::recursive_mutex>, std::unique_lock<std::recursive_mutex> >::Enter(char const*, char const*, int) (this=0x7ffe0a15b018, pszFile=<optimized out>, nLine=467, pszName=<optimized out>)
8 at …/bitcoin/src/sync.h:145
9[#7](/bitcoin-core-gui/7/) UniqueLock<AnnotatedMixin<std::recursive_mutex>, std::unique_lock<std::recursive_mutex> >::UniqueLock(AnnotatedMixin<std::recursive_mutex>&, char const*, char const*, int, bool)
10 (this=0x7ffe0a15b018, mutexIn=..., pszFile=<optimized out>, nLine=467, fTry=false, pszName=<optimized out>) at …/bitcoin/src/sync.h:166
11[#8](/bitcoin-core-gui/8/) node::(anonymous namespace)::ChainImpl::findBlock(uint256 const&, interfaces::FoundBlock const&) (this=0x55b74af4f6a0, hash=..., block=...) at …/bitcoin/src/node/interfaces.cpp:467
12[#9](/bitcoin-core-gui/9/) 0x000055b74897f152 in wallet::(anonymous namespace)::WalletImpl::tryGetTxStatus(uint256 const&, interfaces::WalletTxStatus&, int&, long&)
13 (this=0x55b74b2ec6e0, txid=..., tx_status=..., num_blocks=@0x7ffe0a15b144: 674028, block_time=<optimized out>) at …/bitcoin/src/wallet/interfaces.cpp:333
14[#10](/bitcoin-core-gui/10/) 0x000055b7485c88f8 in TransactionTablePriv::index(interfaces::Wallet&, uint256 const&, int) (this=<optimized out>, wallet=..., cur_block_hash=..., idx=235)
15 at …/bitcoin/src/qt/transactiontablemodel.cpp:221
16[#11](/bitcoin-core-gui/11/) 0x000055b7485c6cc7 in TransactionTableModel::index(int, int, QModelIndex const&) const (this=0x55b74b3e1090, row=235, column=0, parent=...) at …/bitcoin/src/qt/transactiontablemodel.cpp:699
17[#12](/bitcoin-core-gui/12/) 0x000055b7485c21ce in TransactionFilterProxy::filterAcceptsRow(int, QModelIndex const&) const (this=0x55b74b261e50, sourceRow=2, sourceParent=...) at …/bitcoin/src/qt/transactionfilterproxy.cpp:32
18[#13](/bitcoin-core-gui/13/) 0x00007f2ccc7da1bb in () at /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
19[#14](/bitcoin-core-gui/14/) 0x00007f2ccc7dda5b in QSortFilterProxyModel::rowCount(QModelIndex const&) const () at /usr/lib/x86_64-linux-gnu/libQt5Core.so.5
20[#15](/bitcoin-core-gui/15/) 0x000055b7485c2912 in TransactionFilterProxy::rowCount(QModelIndex const&) const (this=0x55b74b261e50, parent=...) at …/bitcoin/src/qt/transactionfilterproxy.cpp:113
All threads:
0(gdb) info threads
1 Id Target Id Frame
2* 1 Thread 0x7f2cc806ea80 (LWP 448041) "bitcoin-qt" __lll_lock_wait (futex=futex@entry=0x55b749266208 <cs_main>, private=0) at lowlevellock.c:52
3 2 Thread 0x7f2cc7122700 (LWP 448042) "QXcbEventQueue" 0x00007f2ccaeefaff in __GI___poll (fds=0x7f2cc7121a28, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
4 3 Thread 0x7f2cc567e700 (LWP 448043) "gmain" 0x00007f2ccaeefaff in __GI___poll (fds=0x55b74ac3d680, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
5 4 Thread 0x7f2cc4e7d700 (LWP 448044) "gdbus" 0x00007f2ccaeefaff in __GI___poll (fds=0x55b74ac00d00, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
6 5 Thread 0x7f2cb7fff700 (LWP 448045) "QDBusConnection" 0x00007f2ccaeefaff in __GI___poll (fds=0x7f2cb00185a0, nfds=7, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
7 6 Thread 0x7f2cb55c6700 (LWP 448046) "bitcoin:disk$0" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b74b36ab58) at ../sysdeps/nptl/futex-internal.h:183
8 7 Thread 0x7f2cb4dc5700 (LWP 448047) "bitcoin:disk$1" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b74b36ab58) at ../sysdeps/nptl/futex-internal.h:183
9 8 Thread 0x7f2cab05b700 (LWP 448048) "bitcoin:disk$2" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b74b36ab58) at ../sysdeps/nptl/futex-internal.h:183
10 9 Thread 0x7f2caa85a700 (LWP 448049) "bitcoin:disk$3" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b74b36ab58) at ../sysdeps/nptl/futex-internal.h:183
11 10 Thread 0x7f2caa059700 (LWP 448050) "b-qt-init" 0x00007f2ccaeefaff in __GI___poll (fds=0x7f2c90001be0, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
12 11 Thread 0x7f2ca8857700 (LWP 448051) "b-scriptch.0" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b74926baa0 <scriptcheckqueue+80>) at ../sysdeps/nptl/futex-internal.h:183
13 12 Thread 0x7f2c96ffe700 (LWP 448052) "b-scriptch.1" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b74926baa0 <scriptcheckqueue+80>) at ../sysdeps/nptl/futex-internal.h:183
14 13 Thread 0x7f2c967fd700 (LWP 448053) "b-scriptch.2" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b74926baa0 <scriptcheckqueue+80>) at ../sysdeps/nptl/futex-internal.h:183
15 14 Thread 0x7f2c95ffc700 (LWP 448054) "b-scriptch.3" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b74926baa0 <scriptcheckqueue+80>) at ../sysdeps/nptl/futex-internal.h:183
16 15 Thread 0x7f2c957fb700 (LWP 448055) "b-scriptch.4" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b74926baa0 <scriptcheckqueue+80>) at ../sysdeps/nptl/futex-internal.h:183
17 16 Thread 0x7f2c94ffa700 (LWP 448056) "b-scheduler" __lll_lock_wait (futex=futex@entry=0x55b749266208 <cs_main>, private=0) at lowlevellock.c:52
18 17 Thread 0x7f2c77fff700 (LWP 448057) "b-http" 0x00007f2ccaefc5ce in epoll_wait (epfd=30, events=0x7f2c9006ec60, maxevents=32, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
19 18 Thread 0x7f2c777fe700 (LWP 448058) "b-httpworker.0" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7f2c90059590) at ../sysdeps/nptl/futex-internal.h:183
20 19 Thread 0x7f2c76ffd700 (LWP 448059) "b-httpworker.1" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7f2c90059590) at ../sysdeps/nptl/futex-internal.h:183
21 20 Thread 0x7f2c767fc700 (LWP 448060) "b-httpworker.2" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7f2c90059590) at ../sysdeps/nptl/futex-internal.h:183
22 21 Thread 0x7f2c75ffb700 (LWP 448061) "b-httpworker.3" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7f2c90059590) at ../sysdeps/nptl/futex-internal.h:183
23 22 Thread 0x7f2c53fff700 (LWP 448063) "b-qt-init" futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55b749273a30 <leveldb::Env::Default()::env_container+88>)
24 at ../sysdeps/nptl/futex-internal.h:183
25 23 Thread 0x7f2c53040700 (LWP 448064) "b-loadblk" __lll_lock_wait (futex=futex@entry=0x55b749266208 <cs_main>, private=0) at lowlevellock.c:52
26 24 Thread 0x7f2c5262d700 (LWP 448065) "b-net" 0x00007f2ccaeefaff in __GI___poll (fds=0x7f2c40016760, nfds=2, timeout=50) at ../sysdeps/unix/sysv/linux/poll.c:29
27 25 Thread 0x7f2c51e2c700 (LWP 448066) "b-addcon" futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0x7f2c51e2b990, clockid=<optimized out>, expected=0, futex_word=0x7f2c9047adc0)
28 at ../sysdeps/nptl/futex-internal.h:320
29 26 Thread 0x7f2c5162b700 (LWP 448067) "b-opencon" __lll_lock_wait (futex=futex@entry=0x55b749266208 <cs_main>, private=0) at lowlevellock.c:52
30 27 Thread 0x7f2c50e2a700 (LWP 448068) "b-msghand" leveldb::crc32c::Unmask (masked_crc=<optimized out>) at …/bitcoin/src/leveldb/util/crc32c.h:36
31 28 Thread 0x7f2c37fff700 (LWP 448069) "b-qt-clientmodl" __lll_lock_wait (futex=futex@entry=0x7f2c9005e1c0, private=0) at lowlevellock.c:52
32 29 Thread 0x7f2c377fe700 (LWP 448070) "b-qt-rpcconsole" 0x00007f2ccaeefaff in __GI___poll (fds=0x7f2c28001be0, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
33 30 Thread 0x7f2c36ffd700 (LWP 448072) "b-qt-walletctrl" 0x00007f2ccaeefaff in __GI___poll (fds=0x7f2c2c001be0, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
To me it looks like msghand is holding up all the other threads probably through cs_main:
0[#0](/bitcoin-core-gui/0/) leveldb::crc32c::Unmask(unsigned int) (masked_crc=<optimized out>) at …/bitcoin/src/leveldb/util/crc32c.h:36
1[#1](/bitcoin-core-gui/1/) leveldb::ReadBlock(leveldb::RandomAccessFile*, leveldb::ReadOptions const&, leveldb::BlockHandle const&, leveldb::BlockContents*) (file=0x7f2c383cc890, options=..., handle=..., result=0x7f2c50e28208)
2 at …/bitcoin/src/leveldb/table/format.cc:88 [#2](/bitcoin-core-gui/2/) 0x000055b748c1d6d8 in leveldb::Table::BlockReader(void*, leveldb::ReadOptions const&, leveldb::Slice const&) (arg=0x7f2c383cce80, options=..., index_value=...)
3 at …/bitcoin/src/leveldb/table/table.cc:179
4[#3](/bitcoin-core-gui/3/) 0x000055b748c1da65 in leveldb::Table::InternalGet(leveldb::ReadOptions const&, leveldb::Slice const&, void*, void (*)(void*, leveldb::Slice const&, leveldb::Slice const&))
5 (this=0x7f2c383cce80, options=..., k=..., arg=0x7f2c50e28490, handle_result=0x55b748c17270 <leveldb::SaveValue(void*, leveldb::Slice const&, leveldb::Slice const&)>)
6 at …/bitcoin/src/leveldb/table/table.cc:230
7[#4](/bitcoin-core-gui/4/) 0x000055b748c0e3af in leveldb::TableCache::Get(leveldb::ReadOptions const&, unsigned long, unsigned long, leveldb::Slice const&, void*, void (*)(void*, leveldb::Slice const&, leveldb::Slice const&))
8 (this=0x7f2c90403710, options=..., file_number=<optimized out>, file_size=<optimized out>, k=..., arg=0x7f2c50e28490, handle_result=0x55b748c17270 <leveldb::SaveValue(void*, leveldb::Slice const&, leveldb::Slice const&)>)
9 at …/bitcoin/src/leveldb/db/table_cache.cc:108
10⋮
11[#16](/bitcoin-core-gui/16/) 0x000055b748b46bba in CCoinsViewCache::HaveCoin(COutPoint const&) const (this=0x7f2c50e28148, outpoint=...) at …/bitcoin/src/coins.cpp:147
12[#17](/bitcoin-core-gui/17/) 0x000055b748b473e0 in CCoinsViewCache::HaveInputs(CTransaction const&) const (this=0x7f2c50e28dd0, tx=...) at …/bitcoin/src/coins.cpp:246
13[#18](/bitcoin-core-gui/18/) 0x000055b7488f6e61 in Consensus::CheckTxInputs(CTransaction const&, TxValidationState&, CCoinsViewCache const&, int, long&) (tx=..., state=..., inputs=..., nSpendHeight=674029, txfee=@0x7f2c50e28c80: 0)
14 at …/bitcoin/src/consensus/tx_verify.cpp:162
15⋮
16[#22](/bitcoin-core-gui/22/) 0x000055b74888c810 in CChainState::ActivateBestChain(BlockValidationState&, CChainParams const&, std::shared_ptr<CBlock const>) (this=<optimized out>, state=..., chainparams=..., pblock=warning: RTTI symbol not found for cla
17ss 'std::_Sp_counted_ptr_inplace<CBlock, std::allocator<CBlock>, (__gnu_cxx::_Lock_policy)2>'
18warning: RTTI symbol not found for class 'std::_Sp_counted_ptr_inplace<CBlock, std::allocator<CBlock>, (__gnu_cxx::_Lock_policy)2>'
19
20std::shared_ptr<const CBlock> (use count 5, weak count 0) = {...}) at …/bitcoin/src/validation.cpp:2894
21[#23](/bitcoin-core-gui/23/) 0x000055b748896e49 in ChainstateManager::ProcessNewBlock(CChainParams const&, std::shared_ptr<CBlock const>, bool, bool*) (this=0x55b74926b760 <g_chainman>, chainparams=..., pblock=warning: RTTI symbol not found for class 's
22td::_Sp_counted_ptr_inplace<CBlock, std::allocator<CBlock>, (__gnu_cxx::_Lock_policy)2>'
23[#24](/bitcoin-core-gui/24/) 0x000055b748675227 in (anonymous namespace)::PeerManagerImpl::ProcessMessage(CNode&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, CDataStream&, std::chrono::duration<long, std::rati
24o<1l, 1000000l> >, std::atomic<bool> const&)
So it seems it received a block from a peer (immediately after connection), now is validating it, which holds up the GUI wallet model’s initial synchronization process for the transaction list.
This makes it a race condition but luckily a harmless one, however it can be frustrating to users for the main UI to take so long to appear.
