Skip to content

AsyncBacking: Parachain blocks produced after 1 minute #9227

@lexnv

Description

@lexnv

AHK manifests a strange behavior were blocks can be produced after 60s:

  • 14400 blocks were scanned
  • 2 occurrences with 10 blocks delay (1min)
  • 3 occurrences with 9 blocks delay (54s)

The average block time production is still roughly 6s, because we are still able to produce multiple blocks with the same timestamp. In doing so, we are basically decreasing the average.

This has been observed while monitoring the AHK to ensure that block number providers are functioning properly. In doing so, the relay chain number that backed the parachain block has advanced 10 blocks, indicating a 1-minute delay in production.

Histogram

  • The histogram shows how many incidents we have seen where the delay between producing 2 AHK blocks is [2..10] relay chain blocks.
Image

Incident

  • T0: AHK produced #10079037 - timestamp 15/07/2025, 16:43:54

  • T1 (1 minute 6 seconds diff): AHK produced #10079038 - timestamp 15/07/2025, 16:45:00

    • This corresponds to Kusama parent #29231263
  • Corresponding session index: 49340

AssetHubKusama: Block #10079036, hash=0xaaf98eb537cf60d99106a946105baded89eca43027be22ab21e1d4d4ff8e257b
  |--> New Author: "0661757261209787b40800000000"
  |--> Timestamp.Set: 0x280503000b20c6530e9801
  |--> Relay Chain Parent: Some(29231252)
  |--> Relay Chain Archive hash for block 29231252: [0x394bd16ad20c818ce7cf3cb84253fce04554af536a17bf58a10be93756ddda05]

    AssetHubKusama: Block #10079037, hash=0x075490dd3cd17d41c1631dae9c15e691b82daea97355618b4a2cc453917f40d7
      |--> Same (times: 2) Author: "0661757261209787b40800000000"
      |--> Timestamp.Set: 0x280503000b90dd530e9801
      |--> Relay Chain Parent: Some(29231253)
      |--> Relay Chain Archive hash for block 29231253: [0x4254b0cbaa03beac67a4ef67181a8c1e44b00c5e1d8267ac2a6486b8c829c18b]

AssetHubKusama: Block #10079038, hash=0x38a98b4845e27c0ead90bad9c3b139802ab3916d09760d7d950f5d3e8ba51506
  |--> New Author: "0661757261209d87b40800000000"
  |--> Timestamp.Set: 0x280503000b60df540e9801
  |--> Relay Chain Parent: Some(29231263)
  |--> Relay Chain Archive hash for block 29231263: [0xe79e8a4c12d55112755e4b13f60ae988e2cb9a37e52325dfb93ecfaa1f3d4057]

    [X] AssetHubKusama: Block #10079039, hash=0x31eb602ddfa988ba52816a2202828133305fdf19c0c94f2f41be9a9bed445137
      |--> Same (times: 2) Author: "0661757261209d87b40800000000"
      |--> (115) Duplicate Timestamp extrinsic found: initial=10079038 current_block=10079039 Timestamp.Set: 0x280503000b60df540e9801

      |--> Relay Chain Parent: Some(29231263)
      |--> Archive hash for block 10079038: [0x38a98b4845e27c0ead90bad9c3b139802ab3916d09760d7d950f5d3e8ba51506]
      |--> Archive hash for block 10079037: [0x075490dd3cd17d41c1631dae9c15e691b82daea97355618b4a2cc453917f40d7]
      |--> Relay Chain Archive hash for block 29231263: [0xe79e8a4c12d55112755e4b13f60ae988e2cb9a37e52325dfb93ecfaa1f3d4057]

        AssetHubKusama: Block #10079040, hash=0xf89db636f1301b032d40b72e86189ed4715dbb5de35c570564d35c3fb68acfa9
          |--> Same (times: 3) Author: "0661757261209d87b40800000000"
          |--> Timestamp.Set: 0x280503000bd0f6540e9801
          |--> Relay Chain Parent: Some(29231264)
          |--> Relay Chain Archive hash for block 29231264: [0x93b423da059c41ce7925c41005ea2c766fe0b9693cb2a8e71527427a3174d254]

AHK During incident

Collator logs during incident: https://grafana.teleport.parity.io/goto/NjjSo5UHR?orgId=1

Image

For live block visualization visit: https://lexnv.github.io/block-visualizer/ with input:

2025-07-15 13:45:12.652  INFO tokio-runtime-worker substrate: [Parachain] 🏆 Imported #10079041 (0xf89d…cfa9 → 0xe8b8…e393)
2025-07-15 13:45:07.294  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079040 (0x31eb…5137 → 0x7e88…822d)
2025-07-15 13:45:06.627  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079040 (0x31eb…5137 → 0xf89d…cfa9)
2025-07-15 13:45:01.393  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079039 (0x19f4…d2a5 → 0xa507…8a12)
2025-07-15 13:45:01.357  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079038 (0x0754…40d7 → 0x19f4…d2a5)
2025-07-15 13:45:00.619  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079039 (0x38a9…1506 → 0x31eb…5137)
2025-07-15 13:45:00.588  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079038 (0x0754…40d7 → 0x38a9…1506)
2025-07-15 13:44:48.927  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079040 (0x36a1…46ff → 0xe602…e214)
2025-07-15 13:44:42.729  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079039 (0xca05…db1f → 0x36a1…46ff)
2025-07-15 13:44:42.674  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079038 (0x0754…40d7 → 0xca05…db1f)
2025-07-15 13:44:24.539  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079040 (0x733a…b020 → 0xa3c5…673b)
2025-07-15 13:44:18.840  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079039 (0x3132…48e0 → 0x733a…b020)
2025-07-15 13:44:18.793  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079038 (0x0754…40d7 → 0x3132…48e0)
2025-07-15 13:44:18.666  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079039 (0x04e0…11d6 → 0x4b6c…69ff)
2025-07-15 13:44:18.627  INFO tokio-runtime-worker substrate: [Parachain] 🆕 Imported #10079038 (0x0754…40d7 → 0x04e0…11d6)
2025-07-15 13:44:12.552  INFO tokio-runtime-worker substrate: [Parachain] 🏆 Imported #10079040 (0x291a…8887 → 0x76b7…abbc)
2025-07-15 13:44:07.032  INFO tokio-runtime-worker substrate: [Parachain] 🏆 Imported #10079039 (0x9d31…04e5 → 0x291a…8887)
2025-07-15 13:44:00.666  INFO tokio-runtime-worker substrate: [Parachain] 🏆 Imported #10079038 (0x0754…40d7 → 0x9d31…04e5)
2025-07-15 13:43:54.722  INFO tokio-runtime-worker substrate: [Parachain] 🏆 Imported #10079037 (0xaaf9…257b → 0x0754…40d7)
2025-07-15 13:43:49.178  INFO tokio-runtime-worker substrate: [Parachain] 🏆 Imported #10079036 (0x712b…c2a7 → 0xaaf9…257b)

Session Index

Grafana link: https://grafana.teleport.parity.io/goto/9Wpf258HR?orgId=1

2025-07-15 14:27:55.471 DEBUG parachain::bitfield-distribution: New gossip topology received session_index=49341 newly_added_peers=60
2025-07-15 14:27:55.422 DEBUG parachain::gossip-support: New session detected session_index=49341
2025-07-15 14:23:54.936 DEBUG parachain::availability-distribution: Validator did not have our chunk validator=Public(782fa188eebb55e96c015cd709f2198b15f593489eed6c7938c0a7708228f020 (FHuQvddM...)) relay_parent=0xac573b9b488d192cebbb71046206e7705cf9814c9164aaba11d0ef86dac6e871 group_index=GroupIndex(75) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0xa17ee442341bc1af8bb695553031dc59b249ff632107d0cbe0cec9f33651d2dc traceID=214664566360121978503829063902061255769
2025-07-15 14:22:18.569 DEBUG parachain::availability-distribution: Validator did not have our chunk validator=Public(a44b80486a22d6904efa6b2b9ee889c875d92ced7f5dcf7c3b09b8ffb3099f78 (GHjoKQER...)) relay_parent=0x21743067bfa48a5ef6d5255d3e888984079d3ba149f1dee2cda848b4e831fef4 group_index=GroupIndex(75) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x793c84d62b2976b742a920b756563df31f1ea6b84d880a814888ffa3bb7d28d2 traceID=161150819547739352352861278436928667123
2025-07-15 14:20:00.677 DEBUG parachain::availability-distribution: Validator did not have our chunk validator=Public(ce38878355311f0b2c1797c4c774fd9afe354c964cbb2f3f3dab5fd772ab5900 (HEiB698c...)) relay_parent=0x8b93e7e9fae0bb09e4597cdbbdd62f7323229f4767fba0e2d5245900c57da888 group_index=GroupIndex(61) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0xd7ec922909cedede92b133c5f470a1a32a286d9218d7316b1f1aeed0c10b15e6 traceID=287012365635563384501710840106948010403
2025-07-15 14:18:07.815 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(3cd7c7e151600570dc4a1e6e3d3ed31f4c9c4e747c755c865ce879fb754e664c (Dx6VSUiz...)) relay_parent=0xaaf5f60a3aae2e910402dccc55c1a95ac4ec9a582d6358302f686fc9076c6ef8 group_index=GroupIndex(62) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x6b902a3e0f7a6947df735f8068bfd2812ded404096ae0a789d137f2ebf714813 err=Network(Timeout) traceID=142975943074754704105376492939892478593
2025-07-15 14:09:38.438 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(880ff4a89f47616390aa21bd9e290f5ddda46b4c6814d97750bf6c933d232966 (FeimcKik...)) relay_parent=0x54b721859773e85eff4a7756b4dbd7e96a762a5e2d56da6625e7b19f4e5c4001 group_index=GroupIndex(65) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x16b523c5d75e5f765e248e5fc6cbee084ca4c90c7ed223f2abb287fad7d18618 err=Network(Timeout) traceID=30183547197600463070135460956717444616
2025-07-15 14:05:31.254 DEBUG parachain::availability-distribution: Validator did not have our chunk validator=Public(fa38a06a2c4a8d8efb677e26f724975b3bbcab7819daca1eff07f426836b1d37 (JEQJy3pB...)) relay_parent=0x347ee1b8d0c986630dec82207a1d5e7383bf43c378f7bbb30d35c3643f8bbbd0 group_index=GroupIndex(61) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x4b1ad7b2b12cde1ed29f214002bb740ef4a8b6ff7563d9d4f7d3da586eed20a6 traceID=99831474277701397042700088684001850382
2025-07-15 14:04:14.289 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(d4fd1808bf6fdc79ca4cec9047c59f245af4e38542319ef2dc329e106f5f2c46 (HParUsky...)) relay_parent=0xf3d721db024348fbe1e51eb914007f63523f1a5efa70ac9945566200a28434c3 group_index=GroupIndex(60) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x8f42c63509981feaa62e2a99d42c556751a02bc0e7873efb8c4a726bf24fd848 err=Network(Timeout) traceID=190426315109069677270328423150919636327
2025-07-15 14:00:37.146 DEBUG parachain::availability-distribution: Validator did not have our chunk validator=Public(5e8c6743a6334aacba7b0ce6d7f5efb89ee5db5606e3dcaafd04e81837be5e60 (EiHj9SHL...)) relay_parent=0x34dc9d6e50b4c82d749a8f94681d6269fa127941f086eb7553e8aed50a22e6a8 group_index=GroupIndex(42) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x23ff6190ea5b4bab3704adff6b8358c17d81fca5b226a7514e04ccd8df3c568d traceID=47848994426515254746627874076213074113
2025-07-15 13:57:30.653 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(8e2738384de39dab0439251228cd5bb962fcd79b0a2e6301c61483898c47f035 (Fnhy6qv8...)) relay_parent=0xd2123f49ba2e3397b25875db07d891af3588b1da138ca9924abb92c9807e92a4 group_index=GroupIndex(36) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x922436921ba0521803962d9f4c7e9000f48da089b0b9f2cc6a76ca5757cad802 err=Refused traceID=194255316897485206584725665272054059008
2025-07-15 13:57:30.649 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(8e2738384de39dab0439251228cd5bb962fcd79b0a2e6301c61483898c47f035 (Fnhy6qv8...)) relay_parent=0xa30931967aabb177f0b3e668ff37b7482cc622b630e03eb857022fb914023c31 group_index=GroupIndex(36) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x676634ec68480ff0ba4fa6ef25297cb1f73320358fa9296a27cb24f8d7fa29cd err=Refused traceID=137441171260836189537021048911087369393
2025-07-15 13:55:42.531 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(d265f488c8068c573d4fdca4ca57c3178e436bde3569002e19b0970f55770146 (HLBrsJbA...)) relay_parent=0x9e339883486a912e240181c62a16971f35cf149c069dcd07b952263a7f7eaee4 group_index=GroupIndex(53) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x31d648a4c5ec6d5353ed0b1c05bfd400a0b4e86ec22f5ebfaf84c1116a8928e0 err=Network(DialFailure) traceID=66244796709351815847721885734335927296
2025-07-15 13:55:42.531 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(d85693be3557892c745067501b57a0a8b71f35eb626f87e8165ee86c73aee737 (HTyaaE1z...)) relay_parent=0x9e339883486a912e240181c62a16971f35cf149c069dcd07b952263a7f7eaee4 group_index=GroupIndex(53) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x31d648a4c5ec6d5353ed0b1c05bfd400a0b4e86ec22f5ebfaf84c1116a8928e0 err=Refused traceID=66244796709351815847721885734335927296
2025-07-15 13:52:30.564 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(3a41e8e0a94935b32f0fee3cec41d65970ad41826733d80eeeff8d12b35c965a (DthsfcF4...)) relay_parent=0x0def2b63071a8590d31c3d69f319b9a38307a852131b1e63c077669ebeb1b093 group_index=GroupIndex(50) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x48acd56ade8a69bc4bd428d81d90d2ad790b91abb16111e141e31efcfc42105d err=Network(DialFailure) traceID=96601819376485740784379487798728643245
2025-07-15 13:40:12.425 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(621adb9016f82b1aaa5b5727b8581428215c6e7d332d7b75a2dd7b83fb08291d (EnxBueT4...)) relay_parent=0x93eefc6e1164c8024891b1a0c25146d021f7371086105d872d386e80617237cb group_index=GroupIndex(38) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x2ca1b5c5d4dc8ed246ed747e384fdf77e21e4e3e42b69e10c10a1e6360a42690 err=Network(DialFailure) traceID=59325678398724142135790226136290549623
2025-07-15 13:29:26.550 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(34308801aa5226e0f59b7043c0593620b2e61a978bbb421288ab8aaf5d90b644 (DkkRaaJU...)) relay_parent=0x0726a762f2ca79f906bd9aa4ea218e45cfe6a5cefcc153e0bfdd10a444768d5e group_index=GroupIndex(12) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x235a28635b1d1309afd3d60e62316352ac3bce53c3f0e89ab266f6789dc88536 err=Network(Timeout) traceID=46991105737910709663352173650999599954
2025-07-15 13:28:23.892 DEBUG parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(ec551b6f0abf951cfe62115ad290533ca8750040ac6113324596ac064fd20904 (HvC6nxKP...)) relay_parent=0x362b290efb59a9a38d2665ce198775e34f130373f04cfd207db2964f4fa3fb8f group_index=GroupIndex(15) session_index=49340 chunk_index=ValidatorIndex(185) candidate_hash=0x5b356650b2ef5c0356e08f3d55ca3cee29c8304fa051b5e09fa14fc2851ad89b err=Network(Timeout) traceID=121237014549339963448492944704001424622
2025-07-15 13:27:55.051 DEBUG parachain::bitfield-distribution: New gossip topology received session_index=49340 newly_added_peers=56
2025-07-15 13:27:55.005 DEBUG parachain::gossip-support: New session detected session_index=49340

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions