[Solved] Bad consensus performance

fredlee · 6 June 2021 17:14

I’m getting really bad vote % with my vNode. Maybe someone (@support) can explain or point me in the right direction.

I am seeing lower than 50% votes on my node and looking at the log, it looks like it is skipping every second one. Here are a few questions about what is logged, maybe someone has the experience to answer.

poolmanager.go:53 [INF] Txpool log :  Received new role 2 committee

Spammed every 3 seconds in the log, is this normal?

Why is syncker.go reporting beacon blocks way ahead of beaconprocess? It goes something like this.

2021-06-04 12:54:00.611 syncker.go:164 [INF] Syncker log : syncker: receive beacon block 1251739 
2021-06-04 12:54:01.201 syncker.go:164 [INF] Syncker log : syncker: receive beacon block 1251740 
2021-06-04 12:54:03.120 beaconprocess.go:108 [INF] BlockChain log: BEACON | InsertBeaconBlock  1251739 with hash 284b422e
2021-06-04 12:54:03.346 beaconprocess.go:187 [INF] BlockChain log: BEACON | Finish Insert new Beacon Block 1251739, with hash 284b422e
2021-06-04 12:55:20.204 syncker.go:164 [INF] Syncker log : syncker: receive beacon block 1251741 
2021-06-04 12:55:21.367 beaconprocess.go:108 [INF] BlockChain log: BEACON | InsertBeaconBlock  1251740 with hash 393e03f0
2021-06-04 12:55:21.586 beaconprocess.go:187 [INF] BlockChain log: BEACON | Finish Insert new Beacon Block 1251740, with hash 393e03f0
2021-06-04 12:55:21.586 beaconprocess.go:108 [INF] BlockChain log: BEACON | InsertBeaconBlock  1251741 with hash 8bee41ec
2021-06-04 12:55:21.756 beaconprocess.go:187 [INF] BlockChain log: BEACON | Finish Insert new Beacon Block 1251741, with hash 8bee41ec

You can see syncker talking about block 1251740, 81 seconds before it shows up in beaconprocess.go. Is this normal or has it something to do with my voting problems shown here:

2021-06-04 12:54:00.611 syncker.go:164 [INF] Syncker log : syncker: receive beacon block 1251739 
2021-06-04 12:54:01.201 syncker.go:164 [INF] Syncker log : syncker: receive beacon block 1251740 

2021-06-04 12:54:03.120 beaconprocess.go:108 [INF] BlockChain log: BEACON | InsertBeaconBlock  1251739 with hash 284b422e
2021-06-04 12:54:03.346 beaconprocess.go:187 [INF] BlockChain log: BEACON | Finish Insert new Beacon Block 1251739, with hash 284b422e

2021-06-04 12:54:40.159 bftactorv3.go:148 [INF] Consensus log: Receive block  33fec235 height 1251601 ,block timeslot  40570282
2021-06-04 12:54:40.172 bftactorv3.go:273 [INF] Consensus log: 
2021-06-04 12:54:40.172 bftactorv3.go:274 [INF] Consensus log: ======================================================
2021-06-04 12:54:40.172 bftactorv3.go:275 [INF] Consensus log: 
2021-06-04 12:54:40.172 bftactorv3.go:277 [INF] Consensus log: shard-2 TS: 40570282, LISTEN BLOCK 1251601, Round 1
2021-06-04 12:54:45.174 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251739 not ready, latest is 1251739
2021-06-04 12:54:45.175 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (1) for block 33fec235 from validator 7
2021-06-04 12:54:50.177 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251739 not ready, latest is 1251739
2021-06-04 12:54:55.181 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251739 not ready, latest is 1251739
2021-06-04 12:55:00.183 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251739 not ready, latest is 1251739
2021-06-04 12:55:05.188 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251739 not ready, latest is 1251739
2021-06-04 12:55:10.191 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251739 not ready, latest is 1251739
2021-06-04 12:55:15.194 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251739 not ready, latest is 1251739
2021-06-04 12:55:20.197 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251739 not ready, latest is 1251739
2021-06-04 12:55:20.198 bftactorv3.go:273 [INF] Consensus log: 
2021-06-04 12:55:20.198 bftactorv3.go:274 [INF] Consensus log: ======================================================
2021-06-04 12:55:20.198 bftactorv3.go:275 [INF] Consensus log: 
2021-06-04 12:55:20.198 bftactorv3.go:277 [INF] Consensus log: shard-2 TS: 40570283, LISTEN BLOCK 1251601, Round 2
2021-06-04 12:55:20.199 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (6) for block 33fec235 from validator 16
2021-06-04 12:55:20.204 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (23) for block 33fec235 from validator 3

2021-06-04 12:55:20.204 syncker.go:164 [INF] Syncker log : syncker: receive beacon block 1251741 

2021-06-04 12:55:20.325 bftactorv3.go:148 [INF] Consensus log: Receive block  818d0009 height 1251602 ,block timeslot  40570283
2021-06-04 12:55:20.528 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (1) for block 818d0009 from validator 5
2021-06-04 12:55:20.536 bftactorv3.go:468 [INF] Consensus log: Number of Valid Vote 23 | Number Of Error Vote 0
2021-06-04 12:55:20.536 bftactorv3.go:480 [INF] Consensus log: Commit block 33fec235 , height: 1251601
2021-06-04 12:55:20.756 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (23) for block 818d0009 from validator 3

2021-06-04 12:55:21.246 syncker.go:164 [INF] Syncker log : syncker: receive beacon block 1251742 

2021-06-04 12:55:21.367 beaconprocess.go:108 [INF] BlockChain log: BEACON | InsertBeaconBlock  1251740 with hash 393e03f0
2021-06-04 12:55:21.586 beaconprocess.go:187 [INF] BlockChain log: BEACON | Finish Insert new Beacon Block 1251740, with hash 393e03f0
2021-06-04 12:55:21.586 beaconprocess.go:108 [INF] BlockChain log: BEACON | InsertBeaconBlock  1251741 with hash 8bee41ec
2021-06-04 12:55:21.756 beaconprocess.go:187 [INF] BlockChain log: BEACON | Finish Insert new Beacon Block 1251741, with hash 8bee41ec

2021-06-04 12:55:21.794 bftactorv3.go:859 [INF] Consensus log: shard-2 sending vote...

2021-06-04 12:55:21.804 bftactorv3.go:468 [INF] Consensus log: Number of Valid Vote 23 | Number Of Error Vote 0
2021-06-04 12:55:21.804 bftactorv3.go:480 [INF] Consensus log: Commit block 818d0009 , height: 1251602
2021-06-04 12:55:21.810 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (24) for block 818d0009 from validator 30
2021-06-04 12:55:21.973 bftactorv3.go:468 [INF] Consensus log: Number of Valid Vote 24 | Number Of Error Vote 0
2021-06-04 12:56:00.172 bftactorv3.go:273 [INF] Consensus log: 
2021-06-04 12:56:00.172 bftactorv3.go:274 [INF] Consensus log: ======================================================
2021-06-04 12:56:00.172 bftactorv3.go:275 [INF] Consensus log: 
2021-06-04 12:56:00.172 bftactorv3.go:277 [INF] Consensus log: shard-2 TS: 40570284, LISTEN BLOCK 1251603, Round 1
2021-06-04 12:56:00.278 bftactorv3.go:148 [INF] Consensus log: Receive block  bc773a9e height 1251603 ,block timeslot  40570284
2021-06-04 12:56:00.293 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (1) for block bc773a9e from validator 4
2021-06-04 12:56:05.375 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251741 not ready, latest is 1251741
2021-06-04 12:56:10.381 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251741 not ready, latest is 1251741
2021-06-04 12:56:15.385 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251741 not ready, latest is 1251741
2021-06-04 12:56:20.389 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251741 not ready, latest is 1251741
2021-06-04 12:56:25.394 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251741 not ready, latest is 1251741
2021-06-04 12:56:30.400 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251741 not ready, latest is 1251741
2021-06-04 12:56:35.404 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251741 not ready, latest is 1251741
2021-06-04 12:56:40.409 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251741 not ready, latest is 1251741
2021-06-04 12:56:40.409 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (11) for block bc773a9e from validator 25
2021-06-04 12:56:40.410 bftactorv3.go:273 [INF] Consensus log: 
2021-06-04 12:56:40.410 bftactorv3.go:274 [INF] Consensus log: ======================================================
2021-06-04 12:56:40.410 bftactorv3.go:275 [INF] Consensus log: 
2021-06-04 12:56:40.410 bftactorv3.go:277 [INF] Consensus log: shard-2 TS: 40570285, LISTEN BLOCK 1251603, Round 2
2021-06-04 12:56:40.411 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (12) for block bc773a9e from validator 20
2021-06-04 12:56:40.413 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (23) for block bc773a9e from validator 19

2021-06-04 12:56:40.433 syncker.go:164 [INF] Syncker log : syncker: receive beacon block 1251743 

2021-06-04 12:56:40.465 bftactorv3.go:203 [INF] Consensus log: shard-2 Receive vote (1) for block 88149d9b from validator 1
2021-06-04 12:56:40.675 bftactorv3.go:480 [INF] Consensus log: Commit block bc773a9e , height: 1251603
2021-06-04 12:56:40.694 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (20) for block 88149d9b from validator 1

2021-06-04 12:56:41.776 beaconprocess.go:108 [INF] BlockChain log: BEACON | InsertBeaconBlock  1251742 with hash 2ae4496f
2021-06-04 12:56:41.992 beaconprocess.go:187 [INF] BlockChain log: BEACON | Finish Insert new Beacon Block 1251742, with hash 2ae4496f

2021-06-04 12:56:45.774 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251742 not ready, latest is 1251742
2021-06-04 12:56:50.792 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251742 not ready, latest is 1251742
2021-06-04 12:56:55.794 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251742 not ready, latest is 1251742
2021-06-04 12:57:00.797 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251742 not ready, latest is 1251742
2021-06-04 12:57:00.797 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (22) for block 88149d9b from validator 3
2021-06-04 12:57:05.800 bftactorv3.go:582 [ERR] Consensus log: Beacon 1251742 not ready, latest is 1251742
2021-06-04 12:57:05.801 bftactorv3.go:468 [INF] Consensus log: Number of Valid Vote 22 | Number Of Error Vote 0
2021-06-04 12:57:05.801 bftactorv3.go:480 [INF] Consensus log: Commit block 88149d9b , height: 1251604
2021-06-04 12:57:05.804 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (23) for block 88149d9b from validator 2

2021-06-04 12:57:05.809 syncker.go:164 [INF] Syncker log : syncker: receive beacon block 1251744 

2021-06-04 12:57:05.999 beaconprocess.go:108 [INF] BlockChain log: BEACON | InsertBeaconBlock  1251743 with hash 1183f6b3
2021-06-04 12:57:06.194 beaconprocess.go:187 [INF] BlockChain log: BEACON | Finish Insert new Beacon Block 1251743, with hash 1183f6b3

2021-06-04 12:57:06.875 bftactorv3.go:859 [INF] Consensus log: shard-2 sending vote...
2021-06-04 12:57:06.876 bftactorv3.go:468 [INF] Consensus log: Number of Valid Vote 23 | Number Of Error Vote 0
2021-06-04 12:57:06.889 bftactorv3.go:173 [INF] Consensus log: shard-2 Receive vote (24) for block 88149d9b from validator 30
2021-06-04 12:57:06.972 bftactorv3.go:420 [INF] Consensus log: Process Block IF enough votes, 88149d9b, 1251604
2021-06-04 12:57:06.973 bftactorv3.go:468 [INF] Consensus log: Number of Valid Vote 24 | Number Of Error Vote 0
2021-06-04 12:57:20.172 bftactorv3.go:273 [INF] Consensus log: 
2021-06-04 12:57:20.172 bftactorv3.go:274 [INF] Consensus log: ======================================================
2021-06-04 12:57:20.172 bftactorv3.go:275 [INF] Consensus log: 
2021-06-04 12:57:20.172 bftactorv3.go:277 [INF] Consensus log: shard-2 TS: 40570286, LISTEN BLOCK 1251605, Round 1

Here you can see that it has inserted beacon block 1251739. Round 1 (33fec235) starts and it starts complaining about “Beacon 1251739 not ready, latest is 1251739” (which is an error message that makes no sense).

It does not log any votes casted and Round 2 (33fec235) starts. Syncker starts talking about block 1251742, and beaconChain pops up and inserts both 1251740 and 1251741 at the same time (why?).

Consensus fires off a vote and then 40 seconds later we start a new round 1 (bc773a9e). Error is back Beacon 1251741 not ready, latest is 1251741.

Round 2 (bc773a9e) starts and error switches to Beacon 1251742 not ready, latest is 1251742.

Syncker starts talking about block 1251744 and beacon inserts 1251743, and consensus fires away its 2nd vote.

My connection is good, there is not much IO load on the server and docker stats tells me around 3-4% CPU use and only 5% memory used.

Epoch vote stats at 48%.

Rocky · 5 June 2021 02:55

@consensus. Please help him!

hyng · 5 June 2021 08:33

About the error line “Beacon 1251739 not ready, latest is 1251739”.
You are the validator of the Shard chain, when a new Shard block is sent, in the header of the shard block contains some beacon blocks, you (I mean your node) have to check if those blocks beacons have been finalized or not. And if those block beacons have not been inserted into your database, or inserted but have not been considered finalize, the consensus engine will report that “Beacon block x not ready, latest is y”. Please refer to this article if you want to understand the multi-view mechanism.
And in your case, it seems that sync or insert block beacon speed is slow. Can you show us more logs, or the whole log file if possible, so we can help you figure out the cause?

fredlee · 5 June 2021 09:40

The message in itself does not make sense since it indicates that the latest block available is the same number it tells me is not ready. If “latest is” refer to what the beacon chain should be, then the information seems irrelevant. Wouldn’t it be better to list what the latest on my node is?

I also see that it was finished inserting 2021-06-04 12:54:03.346 but it keeps giving me errors up to 2021-06-04 12:55:20.197, which is 77s later, after that it’s moving on to round 2.

I’ll PM you a link to my full log for that day.

hyng · 5 June 2021 10:41

I sent you a DM, please check your inbox.

fredlee · 6 June 2021 17:21

@hyng (and team) figured out what was wrong! Thank you guys!

There is confusion regarding the FULLNODE parameter. In the script starting the node, it looks for FULLNODE=1 to see if it should start as a full node. However, in the code, it looks if FULLNODE is set to anything at all. This means that setting FULLNODE=0 ends up not as a full node, and not as a validator node.

Do not set FULLNODE=0, it must be set to FULLNODE= for a validator to work as intended.

fredlee · 10 June 2021 20:27

Can now verify this. I am getting 100% vote results on my epochs.