A problem with Tx Pool draining during async backing testing

[mrshiposha]

During testing the async backing for our parachain on our test stand, we stumbled upon a strange behavior of the tx pool.

In short:
When we send 1000 transactions to the parachain, we expect them to be spread across several blocks, gradually leaving the tx pool.
However, only 30 transactions were executed in two different non-adjacent blocks.
It happens when using the master branch of the polkadot-sdk with async backing enabled.
But works as expected without async backing enabled on polkadot-v1.1.0.

In more detail and a way to reproduce:

• You can use a sudo.sudoUncheckedWeight to execute an extrinsic with a specified weight. Or you can add an extrinsic that allows you to consume the precise amount of weight:

  #[pallet::weight(*w)]
  pub fn consume_block_space(
      origin: OriginFor<T>,
      w: Weight,
  ) -> DispatchResult {
      Ok(())
  }

• Send this transaction 1000 times and make it take exactly 5% of the block space:

  • refTime: 24_875_586_000
  • proofSize: 262_144

  So, we expect 15 transactions in each block (75% of the block since it is a normal-class extrinsic) during the span of 67 blocks.

• With async backing enabled, we see that 15 transactions will appear at a block number N, and another 15 will appear at block N+4 (always at this distance on every run). After that, no transaction will be executed. All of them are dropped.
  Please note that blocks N and N+4 are the first blocks of adjacent unincluded segments.

• Without async backing enabled, 15 transactions appear in each block continuously until all 1000 are executed.

The link to the Unique Network parachain test branch with async backing enabled: https://github.com/uniqueNetwork/unique-chain/tree/test/async-backing.

Possibly related:

• Improve transaction handling for Parachains #1202
• Sassafras Protocol  #41 (as it may alter the transaction handling code)

[bkchr]

Please try running with: #2001

I also assume that you send all the transactions from the same account? If yes, the transaction being dropped are the same reason as I described here: #1202 (comment)

[michalkucharczyk]

If possible, collator's logs with -lparachain=debug, -lbasic-authorship=debug, -ltxpool=debug would be very helpful to assess what is the exact problem in this case. When investigating this problem I saw two problems

• transaction invalid::stale, and
• invalid::future because of reasons explained in Improve transaction handling for Parachains #1202 (comment)

[mrshiposha]

I tried to run the test using multiple accounts, and it worked. So, I assume this issue matches what @bkchr described.

---

Another thing I noticed: I ran the test on another machine, and now the transactions spread randomly from just one block (and then nothing executes) to 3 consecutive blocks executing transactions before dropping.

An example log of the situation where transactions were executed only in one block. The log was collected using the parameters that @michalkucharczyk provided.

The transactions went into block number 4. I see one InvalidTransaction::Stale in there, followed by the "Skipping invalid child transaction while iterating" message.

I stripped the long transaction lists from the log for convenience. I inserted the !!!! NOTE: in their place with a description of what was there.

[bkchr]

Yeah then this issue is a duplicate of: #1202