hang up CPU 100% when init download blocks #8483

bitkevin commented at 10:32 PM on August 7, 2016: contributor

bitcoind v0.12.99
ubuntu 14.04 64bit LTS

$ strace -p 22008, output:

Process 22008 attached
restart_syscall(<... resuming interrupted call ...>) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607751, 528072797}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638257, {1470607751, 728072797}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607751, 728469890}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638259, {1470607751, 928469890}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607751, 928861092}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638261, {1470607752, 128861092}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607752, 129254439}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638263, {1470607752, 329254439}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607752, 329572654}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638265, {1470607752, 529572654}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607752, 529912607}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638267, {1470607752, 729912607}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607752, 730318012}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638269, {1470607752, 930318012}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607752, 930647934}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638271, {1470607753, 130647934}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607753, 130931728}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638273, {1470607753, 330931728}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607753, 331308434}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638275, {1470607753, 531308434}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607753, 531685077}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638277, {1470607753, 731685077}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
futex(0x7ff41afb0d28, FUTEX_WAKE_PRIVATE, 1) = 0
clock_gettime(CLOCK_REALTIME, {1470607753, 731981280}) = 0
futex(0x7ff41afb0d54, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 638279, {1470607753, 931981280}, ffffffff^CProcess 22008 detached
 <detached ...>

debug.log:

2016-08-07 18:56:42 socket sending timeout: 1201s
2016-08-07 18:56:42 socket receive timeout: 1201s
2016-08-07 18:56:43 ping timeout: 1200.047006s
2016-08-07 18:56:43 ping timeout: 1200.047890s
2016-08-07 18:56:44 connect() to 173.199.65.25:8333 failed after select(): Connection refused (111)
2016-08-07 18:57:29 socket sending timeout: 1201s
2016-08-07 18:57:29 socket sending timeout: 1201s
2016-08-07 19:06:56 socket sending timeout: 1201s
2016-08-07 19:07:06 connect() to [2001:0:9d38:6abd:c24:11f9:aaea:6f1d]:8333 failed: Network is unreachable (101)
2016-08-07 19:07:14 socket sending timeout: 1201s
2016-08-07 19:16:44 socket sending timeout: 1201s
2016-08-07 19:26:57 socket sending timeout: 1201s
2016-08-07 19:27:07 connect() to 211.30.183.185:8333 failed after select(): Connection refused (111)
2016-08-07 19:27:09 connect() to 191.19.65.196:8333 failed after select(): Connection refused (111)
2016-08-07 19:27:16 connect() to 1.169.54.122:8333 failed after select(): Connection refused (111)
2016-08-07 19:37:23 connect() to 37.112.18.209:8333 failed after select(): Connection refused (111)
2016-08-07 19:37:23 connect() to 116.6.19.192:8333 failed after select(): Connection refused (111)
2016-08-07 19:37:24 connect() to 162.216.46.8:8333 failed after select(): Connection refused (111)
2016-08-07 19:37:49 connect() to 91.121.23.100:8333 failed after select(): Connection refused (111)
2016-08-07 19:47:34 socket sending timeout: 1201s
2016-08-07 19:48:26 connect() to [2001:0:9d38:90d7:7:3758:a953:2ab5]:8333 failed: Network is unreachable (101)
2016-08-07 19:58:00 connect() to 87.117.141.186:8333 failed after select(): Connection refused (111)
2016-08-07 19:58:07 connect() to 188.120.211.131:8333 failed after select(): Connection refused (111)
2016-08-07 20:07:10 socket sending timeout: 1201s
2016-08-07 20:07:35 socket sending timeout: 1201s
2016-08-07 20:08:34 socket sending timeout: 1201s
2016-08-07 20:17:58 connect() to [2a01:4f8:200:6396::2]:8333 failed: Network is unreachable (101)
2016-08-07 20:18:08 connect() to 37.136.97.9:8333 failed after select(): Connection refused (111)
2016-08-07 20:27:15 socket sending timeout: 1201s
2016-08-07 20:38:05 socket sending timeout: 1201s
2016-08-07 20:38:38 connect() to 108.61.123.75:8333 failed after select(): Connection refused (111)
2016-08-07 20:47:26 connect() to 188.192.45.219:8333 failed after select(): Connection refused (111)
2016-08-07 20:47:34 connect() to 125.27.36.102:8333 failed after select(): Connection refused (111)
2016-08-07 20:48:03 connect() to 187.163.61.141:8333 failed after select(): Connection refused (111)
2016-08-07 20:48:04 connect() to 46.166.173.36:8333 failed after select(): Connection refused (111)
2016-08-07 20:58:45 connect() to 115.72.123.204:8333 failed after select(): Connection refused (111)
2016-08-07 21:18:23 connect() to 184.100.227.91:8333 failed after select(): Connection refused (111)
2016-08-07 21:18:44 socket sending timeout: 1201s
2016-08-07 21:27:39 socket sending timeout: 1201s
2016-08-07 21:27:40 socket sending timeout: 1201s
2016-08-07 21:28:11 connect() to [2001:0:9d38:6ab8:142e:a29c:af95:39cd]:8333 failed: Network is unreachable (101)
2016-08-07 21:39:04 socket sending timeout: 1201s
2016-08-07 21:39:27 connect() to 162.216.46.153:8333 failed after select(): Connection refused (111)
2016-08-07 21:47:44 connect() to 128.52.128.105:8333 failed after select(): Connection refused (111)
2016-08-07 21:47:50 connect() to 198.245.62.62:8333 failed after select(): Connection refused (111)
2016-08-07 21:47:58 connect() to 68.232.186.211:8333 failed after select(): Connection refused (111)
2016-08-07 21:48:40 connect() to 109.201.152.227:8333 failed after select(): Connection refused (111)
2016-08-07 21:58:42 socket sending timeout: 1201s
2016-08-07 21:58:59 connect() to 185.3.135.146:8333 failed after select(): Connection refused (111)
2016-08-07 22:07:51 connect() to 81.83.30.164:8333 failed after select(): Connection refused (111)
2016-08-07 22:08:11 socket sending timeout: 1201s
2016-08-07 22:14:45 tor: Thread interrupt
2016-08-07 22:14:45 torcontrol thread exit
2016-08-07 22:14:45 opencon thread interrupt
2016-08-07 22:14:45 addcon thread interrupt
2016-08-07 22:14:45 scheduler thread interrupt
2016-08-07 22:14:45 net thread interrupt

Leviathn commented at 1:03 AM on August 9, 2016: none

This is the way it is intended to work

sipa commented at 1:09 AM on August 9, 2016: member

To synchronize with the network initially, a few hours of CPU time are necessary to verify all of history. Bitcoin Core tries to do that as fast as possible. You can restrict how many CPU cores it uses with the -par command line option, but it will make the time to being synchronized longer.

jonasschnelli commented at 12:55 PM on August 9, 2016: contributor

I'm not sure if the freezes @bitkevin encounter are normal:

2016-08-07 20:58:45 connect() to 115.72.123.204:8333 failed after select(): Connection refused (111)
2016-08-07 21:18:23 connect() to 184.100.227.91:8333 failed after select(): Connection refused (111)
2016-08-07 21:18:44 socket sending timeout: 1201s

20min no log output seems wrong.

MarcoFalke commented at 5:44 PM on August 9, 2016: member

bitcoind v0.12.99

Can you share the exact version (commit hash) when you are not running a release version?

bitkevin commented at 11:49 PM on August 9, 2016: contributor

@Leviathn I know that verify blocks cause some cpu core 100% but it seems stucked by network I/O lock or something like that. strace show that it looks like lock problem. @MarcoFalke I check out the latest codes from Firbre.

TheBlueMatt commented at 6:17 AM on August 10, 2016: member

@bitkevin Can you gdb and "thread apply all bt"? Would love to see which locks are reversed...additionally, you might try the branch at https://github.com/TheBlueMatt/bitcoin/tree/udp-wip which has lots of updates and may fix your issue.

bitkevin closed this on Aug 15, 2016

bitkevin commented at 2:32 AM on August 15, 2016: contributor

see: https://github.com/bitcoinfibre/bitcoinfibre/issues/2

MarcoFalke locked this on Sep 8, 2021