locking inconsistencies in the network code #4091

In #3997, laanwj wrote:

so it appears that there are some locking inconsistencies in the network code. This is unrelated to the activechain-related locking issues (which only dealt with cs_main and cs_wallet) but worth creating a new issue for

This is that issue.

Here's some debug.log output from a bitcoind (not -qt) that I built from 89bbd54f:

2014-04-24 15:29:24 UpdateTip: new best=00000000000000001fb86ae8e043340da370bb3275a0e4ab4e71c375b3d62f05  height=297495  log2_work=78.191077  tx=37474592  date=2014-04-24 15:29:11 progress=0.999999
2014-04-24 15:29:25 AddToWallet 1b38742b2c3315b9d02d80c9d107e6235205f11ee3d645d0a017c1adedabbeba  
2014-04-24 15:29:25 ProcessBlock: ACCEPTED
2014-04-24 15:36:39 ResendWalletTransactions()
2014-04-24 15:36:39 Relaying wtx 9ea94ab3f30363af36a2ec89e47d93285e3612c5e5084111f0d827d2719ba0e8
2014-04-24 15:36:39 POTENTIAL DEADLOCK DETECTED
2014-04-24 15:36:39 Previous lock order was:
2014-04-24 15:36:39  (1) pnode->cs_vSend  net.cpp:1556
2014-04-24 15:36:39  cs_main  main.cpp:4206
2014-04-24 15:36:39  cs_wallet  wallet.cpp:934
2014-04-24 15:36:39  (2) cs_mapRelay  net.cpp:1845
2014-04-24 15:36:39 Current lock order is:
2014-04-24 15:36:39  pnode->cs_vRecvMsg  net.cpp:1537
2014-04-24 15:36:39  cs_main  main.cpp:3246
2014-04-24 15:36:39  (2) cs_mapRelay  main.cpp:3326
2014-04-24 15:36:39  (1) cs_vSend  net.h:449
2014-04-24 15:45:46 ERROR: AcceptToMemoryPool : nonstandard transaction: dust

Note that the log in #3997 (comment) has more examples of these warnings, and was from a bitcoin-qt built from the same commit.

I've noticed that if I run bitcoin-qt with a large wallet.dat loaded, it locks up for over 3 minutes each time a block is found, with one of the CPU cores using 100% CPU flat out. The debug.log shows:

2014-04-27 20:39:26 UpdateTip: new best=00000000000000005af8d5387a8a595ed2a34167c55b14cdcaa97e5c380f6c7b  height=298031  log2_work=78.256738  tx=37671615  date=2014-04-27 20:38:52 progress=0.999998
2014-04-27 20:39:26 ProcessBlock: ACCEPTED
2014-04-27 20:42:40 ERROR: AcceptToMemoryPool : inputs already spent

Note over 3 minutes of nothing between the 2nd and 3rd lines. Another example:

2014-04-27 20:30:45 UpdateTip: new best=000000000000000020365ab82fbf0d69b29f3c8889acd8241f4bf97951d6995a  height=298028  log2_work=78.256379  tx=37671170  date=2014-04-27 20:31:03 progress=1.000001
2014-04-27 20:30:45 ProcessBlock: ACCEPTED
[3 minute gap]
2014-04-27 20:33:54 Peer 176.67.167.236:8333 is stalling block download, disconnecting
2014-04-27 20:33:54 ERROR: AcceptToMemoryPool : inputs already spent
2014-04-27 20:33:55 ERROR: AcceptToMemoryPool : inputs already spent
2014-04-27 20:33:55 POTENTIAL DEADLOCK DETECTED
2014-04-27 20:33:55 Previous lock order was:
2014-04-27 20:33:55  pnode->cs_vRecvMsg  net.cpp:1537
2014-04-27 20:33:55  (1) cs_main  main.cpp:3718
2014-04-27 20:33:55  (2) cs_vSend  net.h:449
2014-04-27 20:33:55 Current lock order is:
2014-04-27 20:33:55  (2) pnode->cs_vSend  net.cpp:1556
2014-04-27 20:33:55  (1) cs_main  main.cpp:4206
2014-04-27 20:33:55  (1) cs_main  main.cpp:1313
2014-04-27 20:33:55 ERROR: AcceptToMemoryPool : inputs already spent

If I run bitcoind instead, I don't see these delays when blocks are found.

Both bitcoin-qt and bitcoind were built from commit 89bbd54fbfbb1b21257d436731868455821a101e.

Can you profile where it spends all that time?

I still don't have any large-wallet cases to test with, so cannot reproduce this myself.

What tool do you recommend for profiling on Linux?

Also, I think you can make a large wallet by calling 'getnewaddress' in a loop lots of times. I don't know if it matters that they have lots of different labels like my large wallet does.

That wouldn't be a very realistic use case. Large wallets also have lots of incoming and outgoing transactions.

As for profiling, I think using gprof is easiest, although there are many other tools available under Linux such has callgrind, oprofile, sysprofile which may work better in some cases.

I tried a very simple approach of hitting control-C in gdb while it was busy and asking 'where' over and over. All 19 times it reported being in:

[#33](/bitcoin-bitcoin/33/) 0x00005555556611fb in TransactionTableModel::updateConfirmations (
    this=0x5555567373d0) at transactiontablemodel.cpp:264
[#34](/bitcoin-bitcoin/34/) 0x00005555556147ea in WalletModel::pollBalanceChanged (
    this=this@entry=0x55555618d6d0) at walletmodel.cpp:118
[#35](/bitcoin-bitcoin/35/) 0x000055555562c670 in WalletModel::qt_static_metacall (_o=0x55555618d6d0, 
    _c=<optimized out>, _id=10, _a=0x7fffffffd850) at moc_walletmodel.cpp:82
[#36](/bitcoin-bitcoin/36/) 0x00007ffff61ed87a in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /usr/lib/x86_64-linux-gnu/libQtCore.so.4

Is that enough to go on?

I counted each of the file:line references in the 19 backtraces I got. Here are the common ones, with the counts:

 6 transactiontablemodel.cpp:199
 7 transactiontablemodel.cpp:611
 9 transactiontablemodel.cpp:614
10 sync.cpp:42
10 transactiontablemodel.cpp:196
11 sync.cpp:84
14 sync.cpp:123

These line numbers are in a recent HEAD commit c63b2e25a59c602de182a376313ad5d3d62d5045

I notice that 11 of the 19 times I interrupted it, it was running:

LogPrint("lock", "Locking: %s\n", locklocation.ToString());

It seems that CLockLocation::ToString() is heavy.

So probably a case of locking contention. Maybe due to the lock debugging itself. Try turning it off when you do performance profiling :)

With the lock debugging disabled, each new block still ties up the CPU (and freezes the window) for a period of time, but it's less than a minute, rather than being over 3 minutes.

It's now spending all the time here:

[#4](/bitcoin-bitcoin/4/)  0x00007ffff61ed87a in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /usr/lib/x86_64-linux-gnu/libQtCore.so.4
[#5](/bitcoin-bitcoin/5/)  0x00007ffff6237527 in QAbstractItemModel::dataChanged(QModelIndex const&, QModelIndex const&) () from /usr/lib/x86_64-linux-gnu/libQtCore.so.4
[#6](/bitcoin-bitcoin/6/)  0x0000555555660e6b in TransactionTableModel::updateConfirmations (
    this=0x55555685c340) at transactiontablemodel.cpp:264
[#7](/bitcoin-bitcoin/7/)  0x0000555555613909 in WalletModel::pollBalanceChanged (
    this=this@entry=0x555556185d70) at walletmodel.cpp:118

probably a case of locking contention

That wouldn't cause the CPU to get pegged at 100% would it?

That wouldn't cause the CPU to get pegged at 100% would it? @dooglus it could; threads would be fighting over the lock which can certainly max out a CPU

I wonder if it generates data changed events, updating the number of confirmations for every transaction instead of just the ones visible on the screen (which is the intention). Performance here could be improved in any case, thanks for getting to the bottom of this.

I recompiled and profiled with gprof. The output is huge, and I'm not sure how to read it. From what I can see it doesn't draw attention to the call chain I pasted above.

Here are the top few chains it shows:

granularity: each sample hit covers 2 byte(s) for 0.00% of 589.66 seconds

index % time    self  children    called     name
                                                 <spontaneous>
[1]     64.5    0.54  380.06                 TransactionFilterProxy::filterAcceptsRow(int, QModelIndex const&) const [1]
                0.38  319.03 5581880/5582004     QModelIndex::data(int) const [2]
                0.77   59.45  930967/930979      TransactionTableModel::index(int, int, QModelIndex const&) const [18]
                0.10    0.06  930871/930871      QString::contains(QString const&, Qt::CaseSensitivity) const [1309]
                0.09    0.00  930878/930906      QModelIndex::~QModelIndex() [1651]
                0.03    0.05 1861938/26802754     QString::~QString() [483]
                0.06    0.00  931139/931139      QBool::operator void const*() const [1990]
                0.03    0.00  930276/930280      TransactionFilterProxy::TYPE(int) [2654]
                0.02    0.00  930954/931286      QDateTime::operator>(QDateTime const&) const [3129]
-----------------------------------------------
                0.00    0.01     124/5582004     TxViewDelegate::paint(QPainter*, QStyleOptionViewItem const&, QModelIndex const&) const [4489]
                0.38  319.03 5581880/5582004     TransactionFilterProxy::filterAcceptsRow(int, QModelIndex const&) const [1]
[2]     54.2    0.38  319.03 5582004         QModelIndex::data(int) const [2]
                1.47  317.56 5581254/5581254     TransactionTableModel::data(QModelIndex const&, int) const [3]
-----------------------------------------------
                1.47  317.56 5581254/5581254     QModelIndex::data(int) const [2]
[3]     54.1    1.47  317.56 5581254         TransactionTableModel::data(QModelIndex const&, int) const [3]
                0.20  314.05  928783/928808      AddressTableModel::labelForAddress(QString const&) const [4]
                0.39    0.69 24692085/26802754     QString::~QString() [483]
                0.80    0.00 23762806/24299209     QString::fromStdString(std::string const&) [601]
                0.57    0.00 27433453/27433453     QModelIndex::isValid() const [720]
                0.48    0.00 27472122/27472122     QModelIndex::internalPointer() const [791]
                0.32    0.00 21898093/21898093     QModelIndex::column() const [947]
                0.05    0.00  930672/930699      WalletModel::getAddressTableModel() [2157]
                0.00    0.02      19/19          TransactionTableModel::formatTxToAddress(TransactionRecord const*, bool) const [3478]
                0.00    0.00       7/7           TransactionTableModel::addressColor(TransactionRecord const*) const [5141]
                0.00    0.00      20/20          TransactionTableModel::txAddressDecoration(TransactionRecord const*) const [7229]
                0.00    0.00      12/47          QColor::QColor(int, int, int, int) [11149]
-----------------------------------------------
                0.00    0.00       6/928808      TransactionTableModel::addressColor(TransactionRecord const*) const [5141]
                0.00    0.01      19/928808      TransactionTableModel::lookupAddress(std::string const&, bool) const [3479]
                0.20  314.05  928783/928808      TransactionTableModel::data(QModelIndex const&, int) const [3]
[4]     53.3    0.20  314.05  928808         AddressTableModel::labelForAddress(QString const&) const [4]
                0.07  293.29  930445/948840      CBitcoinAddress::CBitcoinAddress(std::string const&) [5]
                0.05   16.44  930124/930124      std::map<boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_>, CAddressBookData, std::less<boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> >, std::allocator<std::pair<boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const, CAddressBookData> > >::find(boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const&) [71]
                0.08    1.52  930850/963023      CBitcoinAddress::Get() const [389]
                0.03    1.03  930542/1025379     CBitcoinAddress::~CBitcoinAddress() [484]
                0.07    0.77  930496/1160916     boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_>::~variant() [538]
                0.02    0.18  930660/96949719     CMutexLock<AnnotatedMixin<boost::recursive_mutex> >::CMutexLock(AnnotatedMixin<boost::recursive_mutex>&, char const*, char const*, int, bool) [52]
                0.09    0.08  930584/930597      QString::toStdString() const [1262]
                0.10    0.03  435584/435827      QString::QString() [1439]
                0.02    0.10  931309/97110659     CMutexLock<AnnotatedMixin<boost::recursive_mutex> >::~CMutexLock() [83]
                0.01    0.03  931733/950129      std::map<boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_>, CAddressBookData, std::less<boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> >, std::allocator<std::pair<boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const, CAddressBookData> > >::end() [2296]
                0.01    0.01  495590/495590      std::_Rb_tree_iterator<std::pair<boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const, CAddressBookData> >::operator->() const [2923]
                0.02    0.00  929474/929474      std::_Rb_tree_iterator<std::pair<boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const, CAddressBookData> >::operator!=(std::_Rb_tree_iterator<std::pair<boost::variant<CNoDestination, CKeyID, CScriptID, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_, boost::detail::variant::void_> const, CAddressBookData> > const&) const [3130]
                0.02    0.00  495034/24299209     QString::fromStdString(std::string const&) [601]
-----------------------------------------------
                0.00    5.80   18395/948840      ReadKeyValue(CWallet*, CDataStream&, CDataStream&, CWalletScanState&, std::string&, std::string&) [44]
                0.07  293.29  930445/948840      AddressTableModel::labelForAddress(QString const&) const [4]
[5]     50.7    0.07  299.08  948840         CBitcoinAddress::CBitcoinAddress(std::string const&) [5]
                0.00  297.94  949944/949944      CBase58Data::SetString(std::string const&) [6]
                0.05    1.10  949931/1026400     CBase58Data::CBase58Data() [467]
-----------------------------------------------
                0.00  297.94  949944/949944      CBitcoinAddress::CBitcoinAddress(std::string const&) [5]
[6]     50.5    0.00  297.94  949944         CBase58Data::SetString(std::string const&) [6]
                0.15  297.79  948495/948495      CBase58Data::SetString(char const*, unsigned int) [7]
-----------------------------------------------

Maybe this is the part of interest:

-----------------------------------------------
                0.00    0.00      12/930979      TransactionTableModel::updateConfirmations() [2287]
                0.77   59.45  930967/930979      TransactionFilterProxy::filterAcceptsRow(int, QModelIndex const&) const [1]
[18]    10.2    0.77   59.45  930979         TransactionTableModel::index(int, int, QModelIndex const&) const [18]
                2.54   55.96 45668847/45668847     TransactionTablePriv::index(int) [19]
                0.47    0.48 22841271/22841273     QAbstractItemModel::createIndex(int, int, void*) const [563]
-----------------------------------------------

Note that the time to load the wallet initially is longer than the delays per block, so that's possibly what's showing up at the top of the list.

I believe the initial report here may have been fixed by #7846.