Initialization reports "Loading banlist..." while doing something else #8117

While starting up a node (commit 6fc6325), it was apparently taking curiously long to load the ban list. RPC (in warmup mode) kept returning Loading banlist.... When I checked the log I happened upon the following:

2016-05-30 07:35:00 init message: Loading banlist...
2016-05-30 07:35:26 UpdateTip: new best=0000000000000000045614e4901f822a86e4015543acc6a68653cc9450f0f330 height=410222 version=0x20000000 log2_work=84.600836 tx=126776938 date='2016-05-04 18:0
1:59' progress=0.984518 cache=8.8MiB(5488tx)
...
2016-05-30 07:39:43 DNS seeding disabled
2016-05-30 07:39:43 opencon thread start
2016-05-30 07:39:43 msghand thread start
2016-05-30 07:39:43 addcon thread start
2016-05-30 07:39:43 init message: Done loading
2016-05-30 07:39:43 net thread start

I think it's a matter of the init message not being updated for a new initialization phase after loading the banlist.

The "Loaded [...] banlist.dat" is currently hidden in the net debug category: https://github.com/bitcoin/bitcoin/blob/d46b8b50fc3e725df75378db2d81aa48f9a1bd74/src/net.cpp#L1974

Managed to catch this in the act:

[#0](/bitcoin-bitcoin/0/)  __libc_do_syscall ()
    at ../ports/sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:43
[#1](/bitcoin-bitcoin/1/)  0xb6f971c0 in __lll_lock_wait (futex=futex@entry=0x7fad1f04 <cs_main>,
    private=<optimized out>)
    at ../ports/sysdeps/unix/sysv/linux/arm/nptl/lowlevellock.c:46
[#2](/bitcoin-bitcoin/2/)  0xb6f93996 in __GI___pthread_mutex_lock (mutex=0x7fad1f04 <cs_main>)
    at pthread_mutex_lock.c:114
[#3](/bitcoin-bitcoin/3/)  0x7f5b0c80 in lock (this=<optimized out>)
    at /data/src/bitcoin-arm/depends/arm-unknown-linux-gnueabihf/include/boost/thread/pthread/recursive_mutex.hpp:113
[#4](/bitcoin-bitcoin/4/)  lock (this=<optimized out>) at sync.h:60
[#5](/bitcoin-bitcoin/5/)  lock (this=0xbeffdff8)
    at /data/src/bitcoin-arm/depends/arm-unknown-linux-gnueabihf/include/boost/thread/lock_types.hpp:346
[#6](/bitcoin-bitcoin/6/)  Enter (pszName=<optimized out>, pszFile=<optimized out>, nLine=2142496176,
    this=0xbeffdff8) at sync.h:125
[#7](/bitcoin-bitcoin/7/)  CMutexLock<CCriticalSection>::CMutexLock (this=0xbeffdff8, mutexIn=...,
    pszName=<optimized out>, pszFile=<optimized out>, nLine=334, fTry=false)
    at sync.h:146
[#8](/bitcoin-bitcoin/8/)  0x7f5c8b48 in (anonymous namespace)::InitializeNode (nodeid=0,
    pnode=0xbeffe204) at main.cpp:334
[#9](/bitcoin-bitcoin/9/)  0x7f6626e4 in operator() (a1=<optimized out>, a0=<optimized out>,
    this=<optimized out>)
    at /data/src/bitcoin-arm/depends/arm-unknown-linux-gnueabihf/include/boost/function/function_template.hpp:771
[#10](/bitcoin-bitcoin/10/) m_invoke<boost::function<void(int, const CNode*)>, 0u, 1u, int&, const CNode*&> (args=..., func=..., this=<optimized out>)
    at /data/src/bitcoin-arm/depends/arm-unknown-linux-gnueabihf/include/boost/signals2/detail/variadic_slot_invoker.hpp:95
[#11](/bitcoin-bitcoin/11/) operator()<boost::function<void(int, const CNode*)>, int&, const CNode*&, 2u> (args=..., func=..., this=<optimized out>)
    at /data/src/bitcoin-arm/depends/arm-unknown-linux-gnueabihf/include/boost/signals2/detail/variadic_slot_invoker.hpp:80
[#12](/bitcoin-bitcoin/12/) operator()<boost::shared_ptr<boost::signals2::detail::connection_body<std::pair<boost::signals2::detail::slot_meta_group, boost::optional<int> >, boost::signals2::slot<void(int, const CNode*), boost::function<void(int, const CNode*)> >, boost::signals2::mutex> > > (connectionBody=..., this=0xbeffe2c8)
    at /data/src/bitcoin-arm/depends/arm-unknown-linux-gnueabihf/include/boost/signals2/detail/variadic_slot_invoker.hpp:124
[#13](/bitcoin-bitcoin/13/) dereference (this=0xbeffe1d0)
    at /data/src/bitcoin-arm/depends/arm-unknown-linux-gnueabihf/include/boost/signals2/detail/slot_call_iterator.hpp:109
[snip]
[#20](/bitcoin-bitcoin/20/) CNode::CNode (this=0x843c6f68, this@entry=0x843c6db8, 
    hSocketIn=hSocketIn@entry=4294967295, addrIn=..., addrNameIn=..., 
    fInboundIn=fInboundIn@entry=false) at net.cpp:2426
[#21](/bitcoin-bitcoin/21/) 0x7f6475c8 in StartNode (threadGroup=..., scheduler=...) at net.cpp:2004
[#22](/bitcoin-bitcoin/22/) 0x7f5a8c14 in AppInit2 (threadGroup=..., scheduler=...) at init.cpp:1416
[#23](/bitcoin-bitcoin/23/) 0x7f58b4a4 in AppInit (argc=2, argv=<optimized out>) at bitcoind.cpp:161
[#24](/bitcoin-bitcoin/24/) 0x7f583450 in main (argc=2, argv=0xbefff414) at bitcoind.cpp:190

So what happens is:

• The call to StartNode in init.cpp ends up in InitializeNode, through the CNode constructor (while creating pnodeLocalHost)
• InitializeNode attempts to get cs_main lock
• However, ActivateBestChain is running in the bitcoin-loadblk thread. This holds the cs_main lock for a long time
• Only after ActivateBestChain finishes, the lock is released, and control flow leaves AppInit2()

This behavior was probably introduced in #7917 (@sipa). It was not the intention. The intention was to move this work to a thread so that it doesn't have to block AppInit2. However due to this perverse case of locking, it ends up that way, with a non-enlightening init message.

Not sure how to fix this though.

Just changing to a better init message (such as "Activating Best Chain") is hard as this happens from so deep in the call tree.

Even though ActivateBestChain is able to release the cs_main since commit 4e0eed8 (#4148), maybe it doesn't do so often enough. It catched up about 16 blocks before initialization could continue.

Maybe we should call boost::this_thread::yield when activating best chain releases cs_main?

Maybe that could help, although I'm not sure how useful a yield still is in multi-core systems. If another thread is waiting on a lock, shouldn't it (at least on average) get it when it is released?

How often is it supposed to release the lock?

It releases the lock after every "strict improvement" to the chainstate. So it won't release during a reorg, or when discovering an invalid block. During normal reindex it should release after every block.

After every block is exactly what I'd expect. Will add some debugging to check that.

Today I had another case of this, but it paused at "init message: Done loading" instead, before showing the main window. The Qt initialization that happens after AppInit2 finishes (in BitcoinApplication::initializeResult) also requires the cs_main lock at some places. Unfortunately this was not on a node with special instrumentation.

Is this a release blocker? If so, some testing of #8392 would be welcome.

No, it's not a release blocker for 0.13. Testing of #8392 would still be welcome, of course.