txpool: execute maintenance on every block (PoC)

[michalkucharczyk]

PoC/Testing: do not merge

Some experimentation towards: #1202

[Sophia-Gold]

I tried running this and am seeing some strange behavior. Based on PoolStatus it appears many transactions are disappearing from the mempool before being pushed and I'm getting a lot of Trying to notify an import but the channel is full.

Here are some snippets from relevant parts of the collator log:

2023-09-05 19:00:42.271 DEBUG tokio-runtime-worker basic-authorship: [Parachain] Attempting to push transactions from the pool.    
2023-09-05 19:00:42.271 DEBUG tokio-runtime-worker basic-authorship: [Parachain] Pool status: PoolStatus { ready: 16000, ready_bytes: 2288000, future: 0, future_bytes: 0 }    
2023-09-05 19:00:42.272 DEBUG tokio-runtime-worker basic-authorship: [Parachain] [0x3072144df8dba902114e873342fdd21dcd7258a3d6f7eb913b5584405d4f3a8d] Pushed to the block.    

...

2023-09-05 19:00:43.930 DEBUG tokio-runtime-worker basic-authorship: [Parachain] Consensus deadline reached when pushing block transactions, proceeding with proposing.    
2023-09-05 19:00:44.029 DEBUG tokio-runtime-worker parachain::approval-voting: [Relaychain] Block finalized block_hash=0xa4035a0c1eb96c71e107f3aecd5339aa2ed14f5e9f2db0b57a22a88de40c2055 block_number=23
2023-09-05 19:00:44.029 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Removing relay parent because our view changed. relay_parent=0x506d5a6677acb39b60f4bc5f7c72153883924767e29533023465433accf63a13
2023-09-05 19:00:44.029 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Collation was requested. candidate_hash=0x344c473a74f8ce1fe8a85a0d5c8098bf2e85bc1056922f4f5e8e0e4bf942ca59 pov_hash=0xe79e80420becee465045767fcb7b93cb6d72b33827abeb5f9fd4006a480aa5ba traceID=69515915024580605525347707601620605119
2023-09-05 19:00:44.029 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Removing relay parent because our view changed. relay_parent=0xdf9fd92f3f4937f4c8131fc4c77df587e38b0db83aa2a80d99386a713577fb27
2023-09-05 19:00:44.029 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Collation was requested. candidate_hash=0x9e4357b561c1484cf971c9b4eb04d939aa81928a20a556997cda2f56fecd0ebc pov_hash=0x62074e3a8ff32bae127190401589e6dfbda214e7b8294b5cde43a5a99b77d2e6 traceID=210367686163725184213254827300759066937
2023-09-05 19:00:44.032  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [Parachain] 🎁 Prepared block for proposing at 8 (1997 ms) [hash: 0x0203a2e94ec2d6532aad3742606a9eaa6f46bfc48c3c13143b40666125b9285c; parent_hash: 0x692c…7629; extrinsics (3544): [0xcd1a…e06f, 0x54c2…099b, 0x3072…3a8d, 0xe118…27c9, 0xf69e…46aa, 0xded1…c5a6, 0x5bcf…3666, 0xbcbd…5d5b, 0x7c58…5bda, 0x9620…443c, 0x9c68…8ece, 0x5466…1ff0, 0x9d26…15d7, 0x6ad9…5a59, 0x9731…82ae, 0x0d85…5d06,

...

2023-09-05 19:00:44.035  INFO tokio-runtime-worker aura::cumulus: [Parachain] 🔖 Pre-sealed block for proposal at 8. Hash now 0xe4299fb27785b01de6d9ea9f978ae3af7f3d9eb3aed7bb4d4615cea5c755a0e0, previously 0x0203a2e94ec2d6532aad3742606a9eaa6f46bfc48c3c13143b40666125b9285c.
2023-09-05 19:00:44.068  INFO tokio-runtime-worker substrate: [Parachain] ✨ Imported #8 (0xe429…a0e0)    
2023-09-05 19:00:44.091  INFO tokio-runtime-worker aura::cumulus: [Parachain] PoV size { header: 0.216796875kb, extrinsics: 498.0966796875kb, storage_proof: 887.2490234375kb }
2023-09-05 19:00:44.091  INFO tokio-runtime-worker aura::cumulus: [Parachain] Compressed PoV size: 840.314453125kb
2023-09-05 19:00:44.121 DEBUG tokio-runtime-worker parachain::collation-generation: [Relaychain] candidate is generated candidate_hash=0x3930de738eed3506eaa99772131cbc176c2f5637c794719e99a594efd374074c pov_hash=0x31561479bc60b3befc6c697025e043b3150d366ed4b18483bce65c5f1060bbe1 relay_parent=0xebfcba25a530dd03802ecda54f2ae683ea70291966f01b6dd9edccb793785a22 para_id=1000 traceID=76019737859354213519812342006041852951
2023-09-05 19:00:44.121 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Received session info session_index=1
2023-09-05 19:00:44.122 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Accepted collation, connecting to validators. para_id=1000 candidate_relay_parent=0xebfc…5a22 relay_parent_mode=Enabled { max_candidate_depth: 3, allowed_ancestry_len: 2 } candidate_hash=0x3930de738eed3506eaa99772131cbc176c2f5637c794719e99a594efd374074c pov_hash=0x31561479bc60b3befc6c697025e043b3150d366ed4b18483bce65c5f1060bbe1 core=CoreIndex(0) current_validators=[Public(d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d (5GrwvaEF...))] traceID=76019737859354213519812342006041852951
2023-09-05 19:00:44.122 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Advertising collation. relay_parent=0xebfcba25a530dd03802ecda54f2ae683ea70291966f01b6dd9edccb793785a22 peer_id=12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm
2023-09-05 19:00:44.122 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators request peer_set=Collation requested=1 failed_to_resolve=0
2023-09-05 19:00:44.122 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Collation num_peers=1 removed=0
2023-09-05 19:00:45.805 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] received an unexpected `CollationSeconded`: unknown statement candidate_hash=0x3930de738eed3506eaa99772131cbc176c2f5637c794719e99a594efd374074c origin=PeerId("12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm") traceID=76019737859354213519812342006041852951
2023-09-05 19:00:48.026  INFO tokio-runtime-worker substrate: [Relaychain] ✨ Imported #26 (0x7d02…6502)    
2023-09-05 19:00:48.028 DEBUG tokio-runtime-worker parachain::availability-store: [Relaychain] Candidate included candidate_hash=0x500e74f4c508a717b39fcdb81563547bc352173707fe5211a4c60e338e93c8b5 traceID=106413303970977441907154481019762201723
2023-09-05 19:00:48.028 DEBUG tokio-runtime-worker parachain::availability-store: [Relaychain] Candidate backed candidate_hash=0x28daf38c8a0e5fcf75f9c34e0204108b6a7c7333260f24611070518f51c1b575 traceID=54305980306759975460705373567284678795
2023-09-05 19:00:48.028 DEBUG tokio-runtime-worker parachain::approval-voting: [Relaychain] Insta-approving 1/1 candidates as the number of validators is too low block_hash=0x7d02556247d43c881c70d03dfdb80d2d45489b564e4bb7b0aadb1a909e1a6502
2023-09-05 19:00:48.028 DEBUG tokio-runtime-worker parachain::approval-voting: [Relaychain] Imported new block. block_number=26 block_hash=0x7d02556247d43c881c70d03dfdb80d2d45489b564e4bb7b0aadb1a909e1a6502 num_candidates=1
2023-09-05 19:00:48.030 DEBUG tokio-runtime-worker parachain::approval-distribution: [Relaychain] Got new blocks [(0x7d02556247d43c881c70d03dfdb80d2d45489b564e4bb7b0aadb1a909e1a6502, 26)]
2023-09-05 19:00:48.030 DEBUG tokio-runtime-worker parachain::approval-distribution: [Relaychain] Processing pending assignment/approvals num=1
2023-09-05 19:00:48.030  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [Parachain] 🙌 Starting consensus session on top of parent 0xe4299fb27785b01de6d9ea9f978ae3af7f3d9eb3aed7bb4d4615cea5c755a0e0    
2023-09-05 19:00:48.032 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Removing relay parent because our view changed. relay_parent=0xa4035a0c1eb96c71e107f3aecd5339aa2ed14f5e9f2db0b57a22a88de40c2055
2023-09-05 19:00:48.032 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Collation was requested. candidate_hash=0x500e74f4c508a717b39fcdb81563547bc352173707fe5211a4c60e338e93c8b5 pov_hash=0x6b076c5a9f56b06c4b3ab5f137df445174e460c8115b4933c06b103676eda78c traceID=106413303970977441907154481019762201723
2023-09-05 19:00:48.032 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Removing relay parent because our view changed. relay_parent=0x128ce48b8b1b2a2e9047d17e0494e5be260226a65256e3ea1b4a477e487ee042
2023-09-05 19:00:48.032 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Collation was requested. candidate_hash=0xfbea8a490df76a218bc04e67656394c164a02ac48f3fd1cc2a488a8d0228ef5e pov_hash=0xd3899fb0480fc939e94859090ed0794f41941b807f2132c228860dfe5bf245bd traceID=334854029167414612230529030207962322113
2023-09-05 19:00:48.032 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Not advertising collation since validator is not interested relay_parent=0xebfcba25a530dd03802ecda54f2ae683ea70291966f01b6dd9edccb793785a22 peer_id=12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm
2023-09-05 19:00:48.032 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Not advertising collation since validator is not interested relay_parent=0x2a298dcb12300c4a26499d78eec4801e6cd968e4f2894fe2b4df08676a23e8d7 peer_id=12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm
2023-09-05 19:00:48.032 DEBUG tokio-runtime-worker basic-authorship: [Parachain] Attempting to push transactions from the pool.    
2023-09-05 19:00:48.032 DEBUG tokio-runtime-worker basic-authorship: [Parachain] Pool status: PoolStatus { ready: 58, ready_bytes: 8294, future: 0, future_bytes: 0 }    
2023-09-05 19:00:48.033 DEBUG tokio-runtime-worker basic-authorship: [Parachain] [0xd2f53b40432905f0aee99fb363f3ef29bb6f0dad233cd91b1a594bb310d8d4e9] Pushed to the block.    

...

2023-09-05 19:00:48.065  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [Parachain] 🎁 Prepared block for proposing at 9 (33 ms) [hash: 0xb6f029c8e417a901404989d52a229f975c3e8178f99bca5223a9fb91e2d028fd; parent_hash: 0xe429…a0e0; extrinsics (60): [0x7f71…6fb5, 0xf513…ff36, 0xd2f5…d4e9, 0x089c…e9a8, 0x93eb…82c1, 0xe7f2…a66a, 0xbd3e…b5b8, 0x8686…cff0, 0x9fa7…5785, 0x0c15…84f7, 0xa568…4e90, 0x0b6c…5fd8, 0x9bcf…a482, 0x920f…ec53, 0x515d…ad09, 0x6e88…7831, 0xc127…71bf, 0xf9fc…4d1e, 0x96b7…138b, 0x49a1…6176, 0x97d6…043b, 0x8ca8…451c, 0xc0c6…827d, 0x91c3…b6db, 0xd5cf…5cb2, 0x0599…17f1, 0x49ca…9ee6, 0x72f6…b541, 0x490d…bf2d, 0x20b7…e197, 0xe16d…1a72, 0xc221…86f7, 0x15a9…4908, 0xa47a…e651, 0xaf27…ce88, 0x9c5f…68fa, 0xb1ac…d879, 0x7efa…a429, 0x4ddb…ea79, 0xa395…e11d, 0x6d86…647a, 0xa988…7822, 0x0c72…6204, 0xbf7e…02e5, 0x7b1c…5790, 0x4662…2bf3, 0xb231…019d, 0xca44…c836, 0xc4d9…f816, 0x060d…97aa, 0x0b67…ec05, 0xc17e…68c2, 0x2758…6003, 0xf058…2c04, 0x8eb3…76ed, 0x0cc4…111b, 0xf3ca…2726, 0xf181…d11a, 0x02c8…1bd3, 0xda8c…42e5]    
2023-09-05 19:00:48.067  INFO tokio-runtime-worker aura::cumulus: [Parachain] 🔖 Pre-sealed block for proposal at 9. Hash now 0x73936a032572935135b71b1e0a325bc9bf46a0e760ade7b4de4dd8e978d6a0cb, previously 0xb6f029c8e417a901404989d52a229f975c3e8178f99bca5223a9fb91e2d028fd.
2023-09-05 19:00:48.069  INFO tokio-runtime-worker substrate: [Parachain] ✨ Imported #9 (0x7393…a0cb)    
2023-09-05 19:00:48.079  INFO tokio-runtime-worker aura::cumulus: [Parachain] PoV size { header: 0.216796875kb, extrinsics: 11.560546875kb, storage_proof: 1212.404296875kb }
2023-09-05 19:00:48.079  INFO tokio-runtime-worker aura::cumulus: [Parachain] Compressed PoV size: 266.861328125kb
2023-09-05 19:00:48.089 DEBUG tokio-runtime-worker parachain::collation-generation: [Relaychain] candidate is generated candidate_hash=0xef883d49f7ffa92d2b2f0344775d207c374cc0b5f97c37b3202b30ce9c37661b pov_hash=0x610dfb6af35a3749dad1dbff77738a9ad34a261c012c656c13125c5014592453 relay_parent=0x7d02556247d43c881c70d03dfdb80d2d45489b564e4bb7b0aadb1a909e1a6502 para_id=1000 traceID=318392886452749188897707300180486594684
2023-09-05 19:00:48.089 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Received session info session_index=1
2023-09-05 19:00:48.090 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Accepted collation, connecting to validators. para_id=1000 candidate_relay_parent=0x7d02…6502 relay_parent_mode=Enabled { max_candidate_depth: 3, allowed_ancestry_len: 2 } candidate_hash=0xef883d49f7ffa92d2b2f0344775d207c374cc0b5f97c37b3202b30ce9c37661b pov_hash=0x610dfb6af35a3749dad1dbff77738a9ad34a261c012c656c13125c5014592453 core=CoreIndex(0) current_validators=[Public(d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d (5GrwvaEF...))] traceID=318392886452749188897707300180486594684
2023-09-05 19:00:48.090 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Advertising collation. relay_parent=0x7d02556247d43c881c70d03dfdb80d2d45489b564e4bb7b0aadb1a909e1a6502 peer_id=12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm
2023-09-05 19:00:48.090 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators request peer_set=Collation requested=1 failed_to_resolve=0
2023-09-05 19:00:48.090 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Collation num_peers=1 removed=0
2023-09-05 19:00:48.159 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] received an unexpected `CollationSeconded`: unknown statement candidate_hash=0xef883d49f7ffa92d2b2f0344775d207c374cc0b5f97c37b3202b30ce9c37661b origin=PeerId("12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm") traceID=318392886452749188897707300180486594684
2023-09-05 19:00:48.451  WARN tokio-runtime-worker txpool: [Parachain] [0xb3f6fd9f5647f9e0d0cc1ba021fd98ddc8a3268a43cfeb0b8abf35e72b1b06c2] Trying to notify an import but the channel is full    
2023-09-05 19:00:48.451  WARN tokio-runtime-worker txpool: [Parachain] [0x399b7cf14459f408ac0a460332d51dd49a6b4c0c30ecd923afaa17bda82c128a] Trying to notify an import but the channel is full    
2023-09-05 19:00:48.451  WARN tokio-runtime-worker txpool: [Parachain] [0x3512c74f25f657e531964eb77aed92f7b85353ce68a2020bc6c66c1fb0a390fe] Trying to notify an import but the channel is full    
2023-09-05 19:00:48.451  WARN tokio-runtime-worker txpool: [Parachain] [0xd5064c27ec7f909f91220b2376c3025d672c15add8da11028630b9752895d2e5] Trying to notify an import but the channel is full    
2023-09-05 19:00:48.451  WARN tokio-runtime-worker txpool: [Parachain] [0x5b322892aa02fcd4d6f847fbe88159a49336ed502c49668e574c43214e7cbec1] Trying to notify an import but the channel is full    
2023-09-05 19:00:48.451  WARN tokio-runtime-worker txpool: [Parachain] [0x93899dd76d4a307f38695f67360bc6b679660be5b22da16e8600a8292c8441a8] Trying to notify an import but the channel is full    
2023-09-05 19:00:48.451  WARN tokio-runtime-worker txpool: [Parachain] [0x2d01c9f46768c83837b5d23fe7a89dea0b8986dad86cb8f6d9b1dfd546c83b58] Trying to notify an import but the channel is full    

etc.

[michalkucharczyk]

@Sophia-Gold would you be willing to share the test setup (zombienet file or scripts/commands that spawn the test network) so I can look into it?

Edited: I added super-simple network setup and js script for sending parachain extrinsic in ef2c52b (+ following fixes) and this setup seems to work in most cases (assuming no blocks getting retracted). If you could provide something similar to share the tests in your configuration I'll be keen on looking into this.

Added files allow to run the zombienet test:

./zombienet-linux -p native test 0008-parachain_extrinsic_gets_finalized.zndsl

or to spawn the network and send transaction manually:

./zombienet-linux -p native spawn 0008-parachain_extrinsic_gets_finalized.toml
node 0008-main.js /tmp/zombie-4071289491ed0a7c713fa789fcf09c87_-3209893-7aI1ggiEOZo7/zombie.json

and sample output for reference:

[[14:08:56.371]] [WARN]  2023-09-06 14:08:56        API/INIT: statemine/10000: Not decorating runtime apis without matching versions: FungiblesApi/2 (1 known)
[[14:08:56.372]] [WARN]  2023-09-06 14:08:56        API/INIT: statemine/10000: Not decorating unknown runtime apis: 0x8a8047a53a8277ec/1
[[14:08:56.411]] [LOG]   Extrinsic status: Ready
[[14:09:06.059]] [LOG]   Extrinsic status: InBlock
[[14:09:06.060]] [LOG]   Included at block hash 0x3aff1f9e41f865cca2f9a79e773b1756e1c3628271e1d126191a830a1f700aae
[[14:09:06.060]] [LOG]   Events:
[[14:09:06.060]] [LOG]           {"applyExtrinsic":2} : balances.Withdraw ["HNZata7iMYWmk5RvZRTiAsSDhV8366zq2YGb3tLH5Upf74F",40732833]
[[14:09:06.061]] [LOG]           {"applyExtrinsic":2} : balances.Deposit ["F3opxRUwkBj1LqjZ7DyiHCRh9Z4zVPLaVjoxfD5ddbip8mt",40732833]
[[14:09:06.061]] [LOG]           {"applyExtrinsic":2} : transactionPayment.TransactionFeePaid ["HNZata7iMYWmk5RvZRTiAsSDhV8366zq2YGb3tLH5Upf74F",40732833,0]
[[14:09:06.062]] [LOG]           {"applyExtrinsic":2} : system.ExtrinsicSuccess [{"weight":{"refTime":126885377,"proofSize":0},"class":"Normal","paysFee":"Yes"}]
[[14:09:33.138]] [LOG]   Extrinsic status: Finalized
[[14:09:33.139]] [LOG]   Finalized block hash 0x3aff1f9e41f865cca2f9a79e773b1756e1c3628271e1d126191a830a1f700aae

(also green in CI)

[Sophia-Gold]

I'm using my feature branch of sTPS: https://github.com/paritytech/polkadot-stps/tree/sophia-parachains. You need to build Polkadot and Polkadot-Parachain from this branch: https://github.com/paritytech/polkadot-sdk/tree/sophia-async-tps with --features network-protocol-staging and copy the binaries in the sTPS directory. Then export PATH=.:$PATH and ./zombienet-linux-x64 test --provider native tests/native/single-para-native.zndsl.

[michalkucharczyk]

Thanks for answer, I'll check this.

Should I set any environment variables? I am specifically asking for this.