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

laanwj commented at 9:40 am on May 30, 2016: member

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:

02016-05-30 07:35:00 init message: Loading banlist...
12016-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
21:59' progress=0.984518 cache=8.8MiB(5488tx)
3...
42016-05-30 07:39:43 DNS seeding disabled
52016-05-30 07:39:43 opencon thread start
62016-05-30 07:39:43 msghand thread start
72016-05-30 07:39:43 addcon thread start
82016-05-30 07:39:43 init message: Done loading
92016-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.

MarcoFalke commented at 2:27 pm on June 5, 2016: member

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

laanwj commented at 12:21 pm on June 6, 2016: member

Managed to catch this in the act:

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

laanwj commented at 12:35 pm on June 6, 2016: member

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.

sipa commented at 12:38 pm on June 6, 2016: member

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

laanwj commented at 12:41 pm on June 6, 2016: member

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?

sipa commented at 12:44 pm on June 6, 2016: member

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.

laanwj commented at 1:01 pm on June 6, 2016: member

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

laanwj commented at 2:38 pm on June 27, 2016: member

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.

sipa commented at 0:50 am on July 30, 2016: member

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

laanwj commented at 8:39 am on August 1, 2016: member

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

laanwj closed this on Aug 4, 2016

DrahtBot locked this on Sep 8, 2021

Initialization reports “Loading banlist…” while doing something else #8117