[DRAFT] Implementing support for emptyBlockPeriodSeconds in QBFT (Issue #3810) #6965
Conversation
…ledger#3810) Signed-off-by: Antonio Mota <antonio.mota@citi.com>
|
Hi @siladu and @matthew1001 can youse please review this one? Cheers. |
There was a problem hiding this comment.
Left a few more comments. Was there any follow up to my earlier comment about what the behaviour should be if a new TX arrives during an empty block interval? I'm not sure waiting the entire remaining empty block interval to include the TX in a block is the right thing to do.
config/src/main/java/org/hyperledger/besu/config/JsonBftConfigOptions.java
Show resolved
Hide resolved
.../common/src/main/java/org/hyperledger/besu/consensus/common/bft/MutableBftConfigOptions.java
Outdated
Show resolved
Hide resolved
...c/main/java/org/hyperledger/besu/consensus/qbft/QbftBlockHeaderValidationRulesetFactory.java
Outdated
Show resolved
Hide resolved
consensus/qbft/src/main/java/org/hyperledger/besu/consensus/qbft/statemachine/QbftRound.java
Show resolved
Hide resolved
Thanks for updating the PR @amsmota I've left a few more comments, the main one being about what the behaviour is when a new TX arrives during the empty block period? |
Hi @matthew1001 , thanks for that. In relation to that comment above I did reply in the previous PR, as per my tests everithing looks OK, please look there the test log. I'll review your new comments ASAP too. Cheers. |
Signed-off-by: amsmota <amsmota@gmail.com>
Signed-off-by: amsmota <amsmota@gmail.com>
|
I've just pulled your latest commits on the PR @amsmota and I'm still seeing the behaviour of a new block not being produced if a TX arrives during the empty block period. E.g. if I have 2 second block interval, 30 second empty block interval the behaviour is:
I'm not sure that's the right behaviour. I think it probably ought to be something like:
It would be good to see what others think though. @siladu any thoughts? |
|
It is not the behaviour I see in my tests. Did you saw the comment I mentioned above? Look at non-empty block 52, it was produced after 5 seconds of the the last empty block and then the next one 30 seconds after (an empty-block). This was with
Can you show me the genesis config you used? And if you can post some logs please do. Anyway, that test was 2 weeks ago, I'll repeat the test asap...
|
Signed-off-by: amsmota <amsmota@gmail.com>
Signed-off-by: amsmota <amsmota@gmail.com>
Signed-off-by: amsmota <amsmota@gmail.com>
Signed-off-by: amsmota <amsmota@gmail.com>
|
Sorry I couldn't find your previous comment, but that's great if that's the current behaviour. I think I pulled and re-built with your latest changes but I'll check. Here's the QBFT config I used: I was using a single node to test though. It's possible that just using a single node gives different behaviour? |
Please note that I'm not dismissing your findings, as I said the tests I did (my original post is in the Issue itself) were done 2 weeks ago, there were some merges and commits by now. I will test again as soon as I can, and I will test the single-node scenario. I suspect that won't behave as intended, at least considering that having my 4 nodes network with 1 node not correctly configured gave me all those issues I mentioned above. My local network of 4 nodes was created following this page. The rest of your comments are now all implemented too. I see below those 4 workflows awaiting approval, what should I do to be able to run them? |
|
Just tested again the emnpty/non-empty block times, it seems good to me. It's based on
The block that contains 1 tx is the line 5: so the flow is 1: --> 30s --> 2: --> 30s --> 3: --> 30s --> 4: --> 10s --> 5: --> 30s --> 6: --> 30s --> 7: --> 30s --> 8: Anyway, to be sure is better if somebody else confirms this data. |
|
One thing I notice in those logs above, in the previous logs I copied from tests all(most) blocks, profuced or imported, appeared on the QbftBesuControllerBuilder output, which is not the case now: I wonder if this is expected ot it may indicate some issue... I actually added some BPs on QbftBesuControllerBuilder and PersistBlockTask to check the upflow but I couldn't see any logic on the diference... |
I've just approved them to run, so they're all going now |
I'll pull your latest commits today and try with a 1 node and 4 node network, but given your findings I expected it's working fine now. |
I'm afraid I found a issue when testing with one node only but unfortunately I couldn't replicate again yet. It seems it happens with 2 non-empty blocks in a row: Block 74 is created correctly but the next one is not, it should take 10 seconds and it took 30... It's this what you observed @matthew1001 ? I'm testing with remix and metamask, and it's hard to send 2 transactions in a row, is there a more expedite way to do it? Cheers. |
Signed-off-by: amsmota <amsmota@gmail.com>
|
I've just pulled your latest changes and re-tested and I do see the same issue still. I've captured some log snippets of Besu with timestamps and a hardhat script with timestamps to can see the timings. This is a 4 validator network with 2 second block period, 30 second empty block period: Here are the Besu logs: Here is the hardhat script which deploys 10 contracts and prints the timestamp before and after: So by |
|
Hi @matthew1001 , that seems different from what I saw in my one-node test, but it's hard for me to test correctly with only remix and metamask. I'm not very familiar with that hardhat, even if I;m installing right now.Can you send me that script so I can test the exact same way as you? Thanks.
|
|
Here's a test I did today with a one-node network based on a 5/10 seconds intervals. Block 3 (the first non-empty) took `10 seconds when it should take 5. However, all the other non-empty blocks seem OK. I'll try again to check if that 1st non-empty block is reproducible... |
|
Here's my latest test with 5/10 seconds, one-node network. I logged some messages to try and understand the issue. You'll notice that the 2 INCORRECT ones have one thing in common, the 2 QbftBlockHeightManager lines have the first saying So after staring at the screen and the occasionally banging my head on the table, I remembered the phrase of that Vulcan guy (or was it Sherlock Holmes?) "When you eliminate the impossible, whatever remains, however improbable, must be the truth" and the only explanation I can find is this: AFAICS the way this works is:
The above is what's happening at the moment, with no emptyBlockPeriodSeconds... With it will be:
So, the only explanation for those INCORRECT blocks is that they got their transaction between the 5th and the 10th second after the previous block... It's only logical... If this explanation is correct, then it's very bad because there is no way to correct it because, well, there's nothing to correct, it's just the way it is... There may be some solution but nothing that comes to mind now... Or I may be wrong, of course... What do you guys think? P.S. I wonder if we can create a PendingTransactionAddedListener in the QbftBlockHeightManager, that may do the trick... |
|
Hi @siladu and @matthew1001 and everybody, I need some help here related to my last comment, at the moment I think this PR is working correctly (if my findings on my last post are correct), I have the idea of having a mempool listener in the QbftBlockHeightManager but I'm afraid that even if that works it'll add too much complexity. Just to recall, the only explanation for the INCORRECT blocks is that the non-empty-bock was created after 10 seconds and not 5 is because the block got the transaction(s) between the 5th and the 10th second after the previous block... Comment PLEASE... |
|
Thanks for doing some extra testing @amsmota At the moment I'm going to find it hard to put the time in to diagnose things in detail. I'm wondering if we want to consider putting the feature in documented as experimental since the basic behaviour seems to work and the exact behaviour in certain situations just needs sorting out. The main thing would be to ensure that we're confident nothing has regressed in the basic case (i.e. when the user hasn't set @siladu what are your thoughts? @non-fungible-nelson do you have a view on whether this could be released as experimental to get more people trying it out and more focus over the coming releases on ironing out any remaining issues? |
Yeah, I totally understand that, and I thank you for your valuable time. 💯
Well, I don't know what exactly implies being "experimental" but I agree with it...
I'm pretty sure that there is no problem there, but looking at the code I do see that there are no provision or validation for that, I may change it to make it explicitly, and anyway I'm going to test that scenario more exhaustively
That part of having more people trying it out I this it's crucial. Being tested by only a couple of persons is too limited, we really need a broader area of testing... Anyway, I'm going to keep on testing, going to create a "standard" test to send transactions in a predefined way, not randomly like I'm doing now, and improve my 4 nodes network because it's very difficult to aggregate meaningful info from all nodes... Thank youse all for your support. |
|
In this test below, with 5/10 seconds, I sent a bunch of transactions with delay of 1 and 8 seconds to the one-node newtork, with this results:
As it shows, all blocks with txs sent with 1 second delay are created with the 5 seconds period, while all the ones with the 8 seconds delay are created with the 10 seconds period (ignore the first 2 blocks, it was probably due to some overhead in my script). This seems to indicate what I said before. If a transaction is sent to the pool between 0-5 secs it will be correctly added, if it is added between 5-10 seconds it will be added after 10 seconds of tha last one. This seems OK, except for the fact that is we have 5/60 seconds to have a transaction sent on the 6th seconds and be added to a block 54 seconds after that it is too much time to wait... I think the problem here is that the code is putting the cart before the horse, meaning that only after the block is created the code knows if it's empty or not. So the correct way to do it is to first peek into the mempool to check if there is ny transaction and then decide what to do... So, considering that I never touched that part of the code, my question is, how can I inspect the Mempool from the QbftBlockHeightManager? |
|
Here's what GoQuorum says about their implementation...
And then some examples that from block 14 onwards it dosen't make much sense to me... I did look at their code, but I'm afraid my Go is a little rust... (pun intended) |
@matthew1001 I am generally in favour of putting things behind an experimental feature, even if they aren't complete. As you mentioned, that is contingent on no regressions when the feature is disabled:
It would be good to have someone who is currently using QBFT in anger test this out and confirm the regression case at least. At the very least, we should test a multi-node network under adversarial conditions, e.g. bringing nodes down to cause a round change, making sure the round change timer is still working as expected (when this feature is disabled). @amsmota here's an example of an experimental feature: Not much to it, basically just a feature flag with an X in front of it and hidden=true in the cli help I'm not sure whether we have an example of an experimental genesis config key. Perhaps it is cleaner to use a CLI flag that you can completely remove later, rather than say |
|
@amsmota I've started the process of testing this as well. I've had a go at writing some acceptance criteria and started working them through here: https://hackmd.io/M2NOd3QKTfCN8Nb_wUNiow
I am also seeing this and concur that I don't think it's expected. From my tests (5 second blockPeriod, 30 second emptyBlockPeriod)...
I think Besu should behave more like GoQuorum in this respect, i.e. once there is a tx in the pool, produce a block no later than the 5 second (non-empty) block period. I do remember this coming up during my draft implementation before, but don't remember what the outcome was, would need to retest my old code to see if and how I avoided it.
I believe the block 14 onwards timestamps are illustrating this behaviour, i.e. a block is produced as soon as the tx is received due to the GoQ's thread that runs a tx "mining" tight loop. Things are starting to come back to me...I think a compromise in my code was to still run on the |
I've tried that approach, on a 5/30 sec block the the blockTimer will expire after 5 secs, then after 5 secs again, and again, and again, and again, and again, until 30 secs are gone and then will create a empty block. The problem is that every 5 seconds if there are txs it should create a block, but as it is now there is no such check (inspect the mempool for txs), what it does now is just create the block and check if that new block is empty or not. So what happened was it was creating empty blocks every 5 seconds. So if I knew how to do that – to inspect the mempool for txs – I think I can implement it that way. But I don't know how to do it... |
So if we are able to check for any txs using the 5 second blockperiodseconds, I would expect EmptyBlock -> tx @ 6 seconds, produces block after 10 seconds (4 seconds after tx sent) |
Sorry, I updated my comment above before I saw yours, I'm on my mobile only and it's hard to update things and check new stuff... Yes, that is what I would expect too... 😁 |
Could be a good use for #7023? |
For sure! Does that exercise the round change timer when it brings nodes down? I think that's probably the most complicated part of the consensus mechanism so a good one to ensure is still working early on. |
I've just retested #4634 and indeed it does produce a block no later than blockperiodseconds after receiving the transaction. I don't inspect the mempool, rather build a block every blockperiodseconds, but only propose it if IIRC, the problems I ran into with my implementation were to do with the round change timer in multi-node networks. |
| case NOT_IMPORTED: | ||
| LOG.info("Block {} was not imported", block.toLogString()); | ||
| break; |
There was a problem hiding this comment.
NOT_IMPORTED doesn't appear to be referenced anywhere else?
There was a problem hiding this comment.
I added it just to show on the logs... I wondered if it ever happened... It can be removed I think...
| roundIdentifier, | ||
| qbftRound.getRoundIdentifier()); | ||
| finalState.getRoundTimer().cancelTimer(); | ||
| finalState.getBlockTimer().startEmptyBlockTimer(roundIdentifier, parentHeader); |
There was a problem hiding this comment.
This case is executed following the blockperiodseconds block timer expiry being handled, so in the context of my test, 5+ seconds after the last block.
Here you are setting the block timer to emptyBlockPeriodSeconds instead of the blockPeriodSeconds, so despite having transactions in the pool, no block building (nor proposal) is attempted until emptyBlockPeriodSeconds (30 seconds) has passed since the last block, at the earliest.
There was a problem hiding this comment.
As mentioned above, GoQuorum QBFT fundamentally differs because of how GoQuorum builds blocks: it follows geth's approach of having a separate thread with a tight block building loop that quickly picks up new transactions in the pool.
Besu QBFT does not have this block building loop running in the background, instead it is event-driven using timers.
It would be a large change to Besu QBFT to support a tight block building loop, but I think for better liveness, ensuring we do something every blockperiodseconds, even if it's just skipping an empty block, is a better approach than waiting the full emptyBlockPeriodSeconds.
There was a problem hiding this comment.
For example, consider if a user were to configure blockPeriodSeconds: 1 along with emptyBlockPeriodSeconds: 600 - I think the user would complain that they had to wait 10 minutes for their transactions to go through
There was a problem hiding this comment.
Yes, we already reached that conclusion. Please read my last comment. It was in reply to your early message...
It definitely stops 1 of the 4 nodes for long enough that block production slows down due to the round expiring for the stopped node, and it also stalls the chain entirely by stopping another node before resuming both and checking that the chain continues once all are back up and running. |
|
But that's what this PR code does, what it shouldn't do is the startEmptyBlockTimer that we already found out it causes the undesirable delay... Yesterday I did change that to the "normal" startTimer, but that caused a succession of empty blocks being created. But I think I know why, I can't check it now (I don't have my laptop with me) but I'll check again as soon as I get home... I think the solution is to use a new BlockTimer or else manipulate the existing one, actually by reusing the startEmptyBlockTimer... |
I would encourage you to check https://github.com/hyperledger/besu/pull/4634/files again since it already implemented the behaviour we're discussing here...maybe run through your tests with it to compare? (Note, I hard-coded I'll admit I've only performed today's tests on a single node network, so maybe I'm missing something for multi-node, but I feel it should work well on a single node before moving onto multi-node testing. As I mentioned above, when I originally tested my PR, I ran into trouble once I got into the more complex test cases such as round changes. |
My code is based on your code, I just moved some stuff to other places, like the BlockTimer. The calculations you did are in my code too (adding the parent timestamp to the emptyblockperiod). It was basically a copy&past and some renaming and in some cases moved to other parts of the code. It doesn't behave as I initially expected because of the way the startEmptyBlockTimer is implemented. I didn't catch that issue before I did because I always tested with very small empty periods, always between 10 and 20, and because I was sending transactions individually, not in a script like I do now. That made the issue less apparent because there were less chances of that happening. I'm pretty confident that after changing the startEmptyBlockTimer things will behave as expected. |
|
Here's the result of the first tests with a 5/30 seconds on a one-node network using the script I had before sending Txs alternating between 1 and 10 seconds intervals. The left columns is the timestamps the Txs were sent. It looks good, all the blocks with Txs were created in the first 5 second frame after being sent. Tomorrow I'll do some tests that mix empty and non-empty blocks, clean the code and commit. |
|
Same test as before but periods of 5/30 and the script sending Txs after a random numbers of seconds between 0 and 60: On the left is the timestamp of the Txs being sent and the number after :::: is the number of seconds that it waited until it sends the next. The Block: X is the number of the block returned by the deploy script. The numbers seem right, every time the wait period is > 30 a new empty block is created, otherwise a non-empty block is created in the next 5 seconds frame after being sent (well, given or taken because I'm not counting the time of the Txs being created). The script could be better written but... it is what is!!! I may write it again to get more accurate times... |
|
And a few more tests, this time with a Transition at Block: 10. It seems all OK to me... Next step, tweak a few logs, clean the code and commit and push. I left the BlockTimer log there so it is visible that it appears every This are the results from the script: |
PR description
Implementing emptyblockperiodseconds for producing empty blocks at a specific interval independently of the value of the existing blockperiodseconds setting
Fixed Issue(s)
#3810
Thanks for sending a pull request! Have you done the following?
doc-change-requiredlabel to this PR if updates are required.Locally, you can run these tests to catch failures early:
./gradlew build./gradlew acceptanceTest./gradlew integrationTest./gradlew ethereum:referenceTests:referenceTests