Block finality lag on v0.9.6 (dev mode)

[pablojorge]

Description

In the release notes of v0.9.6, it reads "This is a client-only release that addresses the current 50 block finality lag on Polkadot.", but we detected that the lag is still present in dev mode.

In the following output, you can see that block #1 is finalized only when the best block is #51

$ ./polkadot/polkadot --dev 
2021-06-23 23:02:30 Running in --dev mode, RPC CORS has been disabled.
2021-06-23 23:02:30 Parity Polkadot
2021-06-23 23:02:30 ✌️  version 0.9.6-63667acb6-x86_64-linux-gnu
2021-06-23 23:02:30 ❤️  by Parity Technologies <admin@parity.io>, 2017-2021
2021-06-23 23:02:30 📋 Chain specification: Development
2021-06-23 23:02:30 🏷 Node name: wanting-cemetery-8911
2021-06-23 23:02:30 👤 Role: AUTHORITY
2021-06-23 23:02:30 💾 Database: RocksDb at /root/.local/share/polkadot/chains/dev/db
2021-06-23 23:02:30 ⛓  Native runtime: polkadot-9050 (parity-polkadot-0.tx7.au0)
2021-06-23 23:02:30 🔨 Initializing Genesis block/state (state: 0x5440…e19f, header-hash: 0xd2c0…8114)
2021-06-23 23:02:30 👴 Loading GRANDPA authority set from genesis on what appears to be first startup.
2021-06-23 23:02:31 ⏱  Loaded block-time = 6s from block 0xd2c0cfb46792acfe001d388fb71120299d9159e0e7bec8751e245a2f4c448114
2021-06-23 23:02:31 👶 Creating empty BABE epoch changes on what appears to be first startup.
2021-06-23 23:02:31 🏷 Local node identity is: 12D3KooWG5YSXzgEJKKtKk6VahAWWzxDqUZGHzbZLFvCbCkXxF4v
2021-06-23 23:02:31 📦 Highest known block at #0
2021-06-23 23:02:31 〽️ Prometheus server started at 127.0.0.1:9615
2021-06-23 23:02:31 Listening for new connections on 127.0.0.1:9944.
2021-06-23 23:02:31 👶 Starting BABE Authorship worker
2021-06-23 23:02:35 🙌 Starting consensus session on top of parent 0xd2c0cfb46792acfe001d388fb71120299d9159e0e7bec8751e245a2f4c448114
2021-06-23 23:02:36 ⌛️ Discarding proposal for slot 270748225; block production took too long
2021-06-23 23:02:36 🙌 Starting consensus session on top of parent 0xd2c0cfb46792acfe001d388fb71120299d9159e0e7bec8751e245a2f4c448114
2021-06-23 23:02:36 🎁 Prepared block for proposing at 1 [hash: 0x0c1fbb6fed50593ae8f3e91499e769d1d2caa19d97cc37e36b2943b208eb863f; parent_hash: 0xd2c0…8114; extrinsics (1): [0x0aff…da62]]
2021-06-23 23:02:36 🎁 Prepared block for proposing at 1 [hash: 0xae7d3e260ad2c0a4f64e7e8042c3a414bc6812f8e8485613b6503d8ab110ec1c; parent_hash: 0xd2c0…8114; extrinsics (1): [0x3519…35c0]]
2021-06-23 23:02:36 🔖 Pre-sealed block for proposal at 1. Hash now 0x92a152795623bdd78d3abb306352880f4c2dd66bc388f8ba357fd1df0b2f6eca, previously 0xae7d3e260ad2c0a4f64e7e8042c3a414bc6812f8e8485613b6503d8ab110ec1c.
2021-06-23 23:02:36 👶 New epoch 0 launching at block 0x92a1…6eca (block slot 270748226 >= start slot 270748226).
2021-06-23 23:02:36 👶 Next epoch starts at slot 270750626
2021-06-23 23:02:36 ✨ Imported #1 (0x92a1…6eca)
2021-06-23 23:02:36 💤 Idle (0 peers), best: #1 (0x92a1…6eca), finalized #0 (0xd2c0…8114), ⬇ 0 ⬆ 0
2021-06-23 23:02:41 💤 Idle (0 peers), best: #1 (0x92a1…6eca), finalized #0 (0xd2c0…8114), ⬇ 0 ⬆ 0
[...]
2021-06-23 23:06:00 🙌 Starting consensus session on top of parent 0x481078dde002ef2f1bfad88af7cb07a114bd45c38be88c479f7e1441771909dc
2021-06-23 23:06:00 🎁 Prepared block for proposing at 35 [hash: 0x005254be63d58278e11ee06f307d8b56403d16b5f6c6a227a7d521a06c4bfb0a; parent_hash: 0x4810…09dc; extrinsics (1): [0x1f70…f469]]
2021-06-23 23:06:00 🔖 Pre-sealed block for proposal at 35. Hash now 0x1aee54ccee11c3031e9d686344270f20a945a9c8121b624821ec18e344c3293e, previously 0x005254be63d58278e11ee06f307d8b56403d16b5f6c6a227a7d521a06c4bfb0a.
2021-06-23 23:06:00 ✨ Imported #35 (0x1aee…293e)
2021-06-23 23:06:01 💤 Idle (0 peers), best: #35 (0x1aee…293e), finalized #0 (0xd2c0…8114), ⬇ 0 ⬆ 0
[...]
2021-06-23 23:07:36 💤 Idle (0 peers), best: #51 (0x319e…2465), finalized #0 (0xd2c0…8114), ⬇ 0 ⬆ 0
2021-06-23 23:07:41 💤 Idle (0 peers), best: #51 (0x319e…2465), finalized #1 (0x92a1…6eca), ⬇ 0 ⬆ 0
2021-06-23 23:07:42 🙌 Starting consensus session on top of parent 0x319eec804fa19dcf01cbf6256a246d0c06f11eb662fcfe2465243ae00e6d2465
2021-06-23 23:07:42 🎁 Prepared block for proposing at 52 [hash: 0x7fc262cd1d1ec32c4b497b076df1e719550e483d7b0987c62a8709201f283bad; parent_hash: 0x319e…2465; extrinsics (1): [0xabd8…091a]]
2021-06-23 23:07:42 🔖 Pre-sealed block for proposal at 52. Hash now 0x11f8a42c916a236174481a92cd0b47d2ccc31f0416c1d59bfc0c75562d986614, previously 0x7fc262cd1d1ec32c4b497b076df1e719550e483d7b0987c62a8709201f283bad.
2021-06-23 23:07:42 ✨ Imported #52 (0x11f8…6614)
2021-06-23 23:07:46 💤 Idle (0 peers), best: #52 (0x11f8…6614), finalized #1 (0x92a1…6eca), ⬇ 0 ⬆ 0

Is this behavior expected? In case it is, is there any way to reduce the lag in this context?

Additional info

In v0.9.3, the lag was the normal 3-4 blocks, this started to happen on v0.9.5, where we could also the following error:

Could not cache session info when processing head. head=0x04beb92ed72d8f111aa78c72c25b6ea7c33a7c33196b66a4be95c608be2fecf2 e=SessionsUnavailable { kind: Missing, info: Some(SessionsUnavailableInfo { window_start: 0, window_end: 0, block_hash: 0x04beb92ed72d8f111aa78c72c25b6ea7c33a7c33196b66a4be95c608be2fecf2 }) }

That error is gone in v0.9.6, but not the lag.