the size of block-template ups and downs when call getblocktemplate at the same block height

[YihaoPeng]

Describe the issue

I run bitcoin-abc v0.16.1 with -rpcthreads=4 (default setting) and -maxblocksize=7994000.

You know there is a lot of unconfirmed transactions in the memory pool recently, so I expect that when I call getblocktemplate, the size of each block-template should be close to 7.9MB.

But I'm wrong. The size of block-template is fluctuant. It sometimes near 1MB, sometimes near 2MB and sometimes near 7.9MB. A size suddenly appeared, keep some seconds, then suddenly switched to another size.

(The issue looks like disappeared if I run bitcoin-abc node with -rpcthreads=1.)

There are some logs about this situation:

I0115 16:33:04.928328   received rawgbt message, len: 21634060
I0115 16:33:05.072896   add rawgbt, height: 513009, gbtTime(UTC): 2018-01-15 08:33:03, isEmpty:0
I0115 16:33:15.891269   received rawgbt message, len: 21636172
I0115 16:33:15.989127   add rawgbt, height: 513009, gbtTime(UTC): 2018-01-15 08:33:14, isEmpty:0
I0115 16:33:27.389917   received rawgbt message, len: 21638664
I0115 16:33:27.552839   add rawgbt, height: 513009, gbtTime(UTC): 2018-01-15 08:33:25, isEmpty:0
I0115 16:33:38.417610   received rawgbt message, len: 21508428
I0115 16:33:38.507400   add rawgbt, height: 513010, gbtTime(UTC): 2018-01-15 08:33:36, isEmpty:0
I0115 16:33:49.523334   received rawgbt message, len: 21511136
I0115 16:33:49.658074   add rawgbt, height: 513010, gbtTime(UTC): 2018-01-15 08:33:47, isEmpty:0
I0115 16:33:51.598462   received rawgbt message, len: 21505568
I0115 16:33:51.764082   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:33:49, isEmpty:0
I0115 16:34:02.312642   received rawgbt message, len: 21507584
I0115 16:34:02.465968   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:34:00, isEmpty:0
I0115 16:34:13.129917   received rawgbt message, len: 21506760
I0115 16:34:13.284595   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:34:11, isEmpty:0
I0115 16:34:24.292460   received rawgbt message, len: 21530444
I0115 16:34:24.382237   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:34:22, isEmpty:0
I0115 16:34:32.951705   received rawgbt message, len: 2402544
I0115 16:34:32.963495   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:34:32, isEmpty:0
I0115 16:34:43.152020   received rawgbt message, len: 2375852
I0115 16:34:43.163635   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:34:42, isEmpty:0
I0115 16:34:53.190088   received rawgbt message, len: 2288400
I0115 16:34:53.204460   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:34:52, isEmpty:0
I0115 16:35:03.263332   received rawgbt message, len: 2296628

The block size nearly equals rawgbt-message-len * 0.37. So the first block template of height 513011 is near 7.9MB (21505568 * 0.37). The next 3 block templates have the similar size. But suddenly, it downs to 879KB (2402544 * 0.37). The block height not changed.

I0115 16:38:46.471782   received rawgbt message, len: 2620808
I0115 16:38:46.492493   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:38:46, isEmpty:0
I0115 16:38:56.529891   received rawgbt message, len: 2555920
I0115 16:38:56.553218   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:38:56, isEmpty:0
I0115 16:39:06.750032   received rawgbt message, len: 2659708
I0115 16:39:06.769505   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:39:06, isEmpty:0
I0115 16:39:19.085886   received rawgbt message, len: 21582256
I0115 16:39:19.177824   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:39:17, isEmpty:0
I0115 16:39:30.235061   received rawgbt message, len: 21562640
I0115 16:39:30.347178   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:39:28, isEmpty:0
I0115 16:39:38.978626   received rawgbt message, len: 2688528
I0115 16:39:38.991443   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:39:38, isEmpty:0
I0115 16:39:49.152184   received rawgbt message, len: 2657560
I0115 16:39:49.170716   add rawgbt, height: 513011, gbtTime(UTC): 2018-01-15 08:39:48, isEmpty:0
I0115 16:39:52.453143   received rawgbt message, len: 2034264
I0115 16:39:52.462138   add rawgbt, height: 513012, gbtTime(UTC): 2018-01-15 08:39:52, isEmpty:0
I0115 16:40:03.223552   received rawgbt message, len: 2132700

Log continues. The len suddenly ups to 21582256 and 21562640 at 16:39:06, then downs to 2688528 immediately.

I0115 16:59:10.023394   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 08:59:09, isEmpty:0
I0115 16:59:20.356853   received rawgbt message, len: 5375140 
I0115 16:59:20.380823   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 08:59:19, isEmpty:0
I0115 16:59:30.489938   received rawgbt message, len: 5274700
I0115 16:59:30.519778   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 08:59:30, isEmpty:0
I0115 16:59:40.934909   received rawgbt message, len: 5272036
I0115 16:59:40.977450   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 08:59:40, isEmpty:0
I0115 16:59:51.084669   received rawgbt message, len: 5347076
I0115 16:59:51.108201   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 08:59:50, isEmpty:0
I0115 17:00:01.281482   received rawgbt message, len: 5254620
I0115 17:00:01.305104   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:00:00, isEmpty:0
I0115 17:00:11.664902   received rawgbt message, len: 5397116
I0115 17:00:11.707098   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:00:11, isEmpty:0
I0115 17:00:21.840302   received rawgbt message, len: 5285952
I0115 17:00:21.861829   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:00:21, isEmpty:0
I0115 17:00:32.288036   received rawgbt message, len: 5441524
I0115 17:00:32.310881   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:00:31, isEmpty:0
I0115 17:00:42.455649   received rawgbt message, len: 5371280
I0115 17:00:42.477411   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:00:42, isEmpty:0
I0115 17:00:52.917096   received rawgbt message, len: 5314756
I0115 17:00:52.955546   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:00:52, isEmpty:0
I0115 17:01:05.370621   received rawgbt message, len: 21662948
I0115 17:01:05.527895   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:01:03, isEmpty:0
I0115 17:01:14.396657   received rawgbt message, len: 5412992
I0115 17:01:14.419031   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:01:13, isEmpty:0
I0115 17:01:24.676014   received rawgbt message, len: 5401480
I0115 17:01:24.698218   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:01:24, isEmpty:0
I0115 17:01:34.883957   received rawgbt message, len: 5330016
I0115 17:01:34.906018   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:01:34, isEmpty:0
I0115 17:01:47.271014   received rawgbt message, len: 21634404
I0115 17:01:47.442257   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:01:45, isEmpty:0
I0115 17:01:56.476725   received rawgbt message, len: 5453676
I0115 17:01:56.510555   add rawgbt, height: 513014, gbtTime(UTC): 2018-01-15 09:01:55, isEmpty:0
I0115 17:02:06.571846   received rawgbt message, len: 5425764

Len: 5330016 -> 21634404 -> 5453676, with the same block height.

Can you reliably reproduce the issue?

If so, please list the steps to reproduce below:

1. run bitcoin-abc v0.16.1 with this bitcoin.conf:

rpcuser=xxx
rpcpassword=xxx
rpcthreads=4

rpcallowip=172.16.0.0/12
rpcallowip=192.168.0.0/16
rpcallowip=10.0.0.0/8

dbcache=1000
blockmaxsize=7994000

2. Call getblocktemplate every ten seconds and record the size of the returned data.

Expected behaviour

The size of block-template is increasing from a small number to near 7.9MB, then keep 7.9MB until a new block found.

Actual behaviour

The size of block-template is fluctuant. It sometimes near 1MB, sometimes near 2MB and sometimes near 7.9MB. A size suddenly appeared, keep some seconds, then suddenly switched to another size.

What version of bitcoin-abc are you using?

Bitcoin-ABC v0.16.1, https://github.com/Bitcoin-ABC/bitcoin-abc/archive/v0.16.1.tar.gz

Running it as a docker container: https://github.com/btccom/bccpool/tree/master/docker/bitcoin-abc/v0.16.1

Machine specs:

• OS: Ubuntu 16.04 LTS
• CPU: Intel(R) Xeon(R) CPU E5-2682 v4 @ 2.50GHz
• RAM: 8GB
• Disk size: 300GB
• Disk Type (HD/SDD): SSD (what's SDD?)

Any extra information that might be useful in the debugging process.

The issue looks like disappeared if I run bitcoin-abc with -rpcthreads=1.

[YihaoPeng]

Oh, -rpcthreads=1 seems not work. I run bitcoin-abc node with -rpcthreads=1 now but I found these logs:

I0115 20:50:04.611034 19684 GbtMaker.cc:234] sumbit to Kafka, msg len: 21827912
I0115 20:50:14.980540 19684 GbtMaker.cc:198] gbt height: 513033, prev_hash: 00000000000000000012c7ef96514da48454d13fefdbe6c69d3f4434fbc23363, coinbase_value: 1259682477, bits: 18039abb, mintime: 1516014614, version: 536870912|0x20000000, gbthash: c3edd0d4d8a743248e8da3e3cf8748a45622b0c5a29536baeb069d94c2d8a3d4
I0115 20:50:15.057153 19684 GbtMaker.cc:234] sumbit to Kafka, msg len: 8205268
I0115 20:50:25.991328 19684 GbtMaker.cc:198] gbt height: 513033, prev_hash: 00000000000000000012c7ef96514da48454d13fefdbe6c69d3f4434fbc23363, coinbase_value: 1264746837, bits: 18039abb, mintime: 1516014614, version: 536870912|0x20000000, gbthash: ed03ab68ed4ee272664d2fda438688f2f20c2945444efba9ac682a91b820b9d0
I0115 20:50:26.191233 19684 GbtMaker.cc:234] sumbit to Kafka, msg len: 21827336
I0115 20:50:37.149384 19684 GbtMaker.cc:198] gbt height: 513033, prev_hash: 00000000000000000012c7ef96514da48454d13fefdbe6c69d3f4434fbc23363, coinbase_value: 1264763151, bits: 18039abb, mintime: 1516014614, version: 536870912|0x20000000, gbthash: f2cc31e4b1eb014d9b9466e7e525af3593c7b00191d8502ba88648a6e60acae7

len: 21827912 -> 8205268 -> 21827336, the block height not changed.
So we mined a near 3MB block (≈ 8205268 * 0.37) by accident.

[deadalnix]

So it is not a multithreading issue, which is somehow reinsuring. Thanks for reporting this.

[kingvest]

I'm unable to reproduce this issue with Bitcoin-ABC v0.16.2

The size of getblocktemplate is increasing steadily

@YihaoPeng - Can you reproduce the issue with 0.16.2?

[YihaoPeng]

I have no 0.16.2 nodes at current and the unconfirmed transactions in memory pool receded.

I will upgrade to 0.16.2 and test it at next time that the memory pool larger than 100MB.

[deadalnix]

I think I now what the problem is. You must have reached the sigops limit. sigops is not taken into account when prioritizing transactions building a template.

[qshuai]

@deadalnix Yeah, you are right(sigops works), I can test 32M block in testnet. Following params will be modified:

static const uint64_t DEFAULT_MAX_BLOCK_SIZE = 32 * ONE_MEGABYTE;
static const int64_t MAX_BLOCK_SIGOPS_PER_MB = 200000;
static const uint64_t DEFAULT_MAX_GENERATED_BLOCK_SIZE = 32 * ONE_MEGABYTE;

[schancel]

@qshuai Thank you for the update. I'm going to close the issue as resolved. Please reopen if there is other follow up needed.