Block production pauses right after segment creation

[nazar-pc]

Here is what happens every time there is a new segment on the mainnet:

node-1  | 2024-12-17T14:43:00.753392Z  INFO Consensus: substrate: 🏆 Imported #575376 (0xb827…26e1 → 0xe981…37a1)    
node-1  | 2024-12-17T14:43:03.154575Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575376 (0xe981…37a1), finalized #464841 (0x6177…4d33), ⬇ 82.6kiB/s ⬆ 52.5kiB/s    
node-1  | 2024-12-17T14:43:08.155155Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575376 (0xe981…37a1), finalized #464841 (0x6177…4d33), ⬇ 62.6kiB/s ⬆ 58.7kiB/s    
node-1  | 2024-12-17T14:43:10.226387Z  INFO Consensus: substrate: 🏆 Imported #575377 (0xe981…37a1 → 0xfc18…d6c2)    
node-1  | 2024-12-17T14:43:13.155627Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 78.9kiB/s ⬆ 48.2kiB/s    
node-1  | 2024-12-17T14:43:18.156073Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 56.0kiB/s ⬆ 52.9kiB/s    
node-1  | 2024-12-17T14:43:23.156701Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 41.3kiB/s ⬆ 41.5kiB/s    
node-1  | 2024-12-17T14:43:28.157104Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 52.4kiB/s ⬆ 54.0kiB/s    
node-1  | 2024-12-17T14:43:33.157827Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 43.1kiB/s ⬆ 44.7kiB/s    
node-1  | 2024-12-17T14:43:38.158191Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 45.8kiB/s ⬆ 46.7kiB/s    
node-1  | 2024-12-17T14:43:43.158694Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 46.9kiB/s ⬆ 48.1kiB/s    
node-1  | 2024-12-17T14:43:48.158966Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 50.6kiB/s ⬆ 51.5kiB/s    
node-1  | 2024-12-17T14:43:53.159546Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 31.3kiB/s ⬆ 31.4kiB/s    
node-1  | 2024-12-17T14:43:58.159887Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 45.5kiB/s ⬆ 47.0kiB/s    
node-1  | 2024-12-17T14:44:03.160273Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 24.4kiB/s ⬆ 23.5kiB/s    
node-1  | 2024-12-17T14:44:08.160729Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 26.4kiB/s ⬆ 26.0kiB/s    
node-1  | 2024-12-17T14:44:13.161072Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 23.3kiB/s ⬆ 22.7kiB/s    
node-1  | 2024-12-17T14:44:18.161419Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 36.9kiB/s ⬆ 38.5kiB/s    
node-1  | 2024-12-17T14:44:23.161666Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 34.9kiB/s ⬆ 36.4kiB/s    
node-1  | 2024-12-17T14:44:28.162096Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 34.0kiB/s ⬆ 34.3kiB/s    
node-1  | 2024-12-17T14:44:33.162573Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 36.7kiB/s ⬆ 39.2kiB/s    
node-1  | 2024-12-17T14:44:38.162808Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 29.5kiB/s ⬆ 30.6kiB/s    
node-1  | 2024-12-17T14:44:43.163110Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 17.9kiB/s ⬆ 17.7kiB/s    
node-1  | 2024-12-17T14:44:48.163582Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 34.7kiB/s ⬆ 31.0kiB/s    
node-1  | 2024-12-17T14:44:53.164312Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 35.1kiB/s ⬆ 24.0kiB/s    
node-1  | 2024-12-17T14:44:58.164737Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 23.1kiB/s ⬆ 18.6kiB/s    
node-1  | 2024-12-17T14:45:03.165265Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 30.7kiB/s ⬆ 21.9kiB/s    
node-1  | 2024-12-17T14:45:08.165927Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 19.0kiB/s ⬆ 17.4kiB/s    
node-1  | 2024-12-17T14:45:13.166296Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 18.4kiB/s ⬆ 17.6kiB/s    
node-1  | 2024-12-17T14:45:18.166870Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 40.2kiB/s ⬆ 31.9kiB/s    
node-1  | 2024-12-17T14:45:23.167548Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 30.9kiB/s ⬆ 18.2kiB/s    
node-1  | 2024-12-17T14:45:28.168014Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575377 (0xfc18…d6c2), finalized #464841 (0x6177…4d33), ⬇ 37.6kiB/s ⬆ 22.1kiB/s    
node-1  | 2024-12-17T14:45:32.321086Z  INFO Consensus: substrate: 🏆 Imported #575378 (0xfc18…d6c2 → 0xd46b…2a01)    
node-1  | 2024-12-17T14:45:32.322004Z  WARN Consensus: sync: 💔 Error importing block 0x65279651e9af3586c3a53510c70fe709aa01cd29a4595805ec5e39e4cfb71321: block has an unknown parent    
node-1  | 2024-12-17T14:45:32.375849Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x14ab…ef29)    
node-1  | 2024-12-17T14:45:32.442129Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0xec03…f524)    
node-1  | 2024-12-17T14:45:32.467325Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x3ec4…09a3)    
node-1  | 2024-12-17T14:45:32.496480Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x368b…f2c6)    
node-1  | 2024-12-17T14:45:32.562414Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x16a4…8cf7)    
node-1  | 2024-12-17T14:45:32.646575Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x3663…d7d9)    
node-1  | 2024-12-17T14:45:32.701335Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x183c…4a46)    
node-1  | 2024-12-17T14:45:32.780311Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0xeb90…f042)    
node-1  | 2024-12-17T14:45:32.804270Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x5eaf…e8cd)    
node-1  | 2024-12-17T14:45:32.917822Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x88f9…cf07)    
node-1  | 2024-12-17T14:45:32.918483Z  WARN Consensus: sync: 💔 Error importing block 0xb4cf65b064c34f9512c3b93d3e6add845af9efe88097e17cc0417d1946ba5d17: block has an unknown parent    
node-1  | 2024-12-17T14:45:32.918719Z  WARN Consensus: sync: 💔 Error importing block 0x6e1ddf5ce0efd1731f3e9446852895710e6b7dc4c9fb79880fd701016e000086: block has an unknown parent    
node-1  | 2024-12-17T14:45:33.015649Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x55a0…d4bf)    
node-1  | 2024-12-17T14:45:33.015933Z  WARN Consensus: sync: 💔 Error importing block 0x6104f92984e9c53abe67b17305cd9c989c17d566a9d8574a701b4aecee191632: block has an unknown parent    
node-1  | 2024-12-17T14:45:33.145556Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0xa368…2a66)    
node-1  | 2024-12-17T14:45:33.168378Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575378 (0xd46b…2a01), finalized #483395 (0xc600…88f1), ⬇ 127.7kiB/s ⬆ 93.3kiB/s    
node-1  | 2024-12-17T14:45:33.212107Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x1834…52b0)    
node-1  | 2024-12-17T14:45:33.212433Z  WARN Consensus: sync: 💔 Error importing block 0x980c3fdcecc86424e3ae0b76c2cc62631178563fa9ffa92846bcf7cc74d0c691: block has an unknown parent    
node-1  | 2024-12-17T14:45:33.212640Z  WARN Consensus: sync: 💔 Error importing block 0x11cfbe48d60ce52faf84eec8b9d5996bb2770377003e5e672c32f584786eb6a3: block has an unknown parent    
node-1  | 2024-12-17T14:45:33.331483Z  INFO Consensus: sc_informant: ♻️  Reorg on #575378,0xd46b…2a01 to #575379,0x6527…1321, common ancestor #575377,0xfc18…d6c2    
node-1  | 2024-12-17T14:45:33.331496Z  INFO Consensus: substrate: 🏆 Imported #575379 (0x368b…f2c6 → 0x6527…1321)    
node-1  | 2024-12-17T14:45:33.331763Z  WARN Consensus: sync: 💔 Error importing block 0x7ba769565ab6fac706eeac5c508f34951891ed470136711721fadfb94491a126: consensus error: Api called for an unknown Block: Header was not found in the database: 0x980c3fdcecc86424e3ae0b76c2cc62631178563fa9ffa92846bcf7cc74d0c691    
node-1  | 2024-12-17T14:45:34.159620Z  INFO Consensus: substrate: 🏆 Imported #575380 (0x6527…1321 → 0xb4cf…5d17)    
node-1  | 2024-12-17T14:45:34.169669Z  INFO Consensus: substrate: 🏆 Imported #575381 (0xb4cf…5d17 → 0x6e1d…0086)    
node-1  | 2024-12-17T14:45:34.177652Z  INFO Consensus: substrate: 🏆 Imported #575382 (0x6e1d…0086 → 0x6104…1632)    
node-1  | 2024-12-17T14:45:34.191990Z  INFO Consensus: substrate: 🏆 Imported #575383 (0x6104…1632 → 0x980c…c691)    
node-1  | 2024-12-17T14:45:34.234477Z  INFO Consensus: substrate: 🏆 Imported #575384 (0x980c…c691 → 0x7ba7…a126)    
node-1  | 2024-12-17T14:45:36.365203Z  INFO Consensus: substrate: 🆕 Imported #575383 (0x6104…1632 → 0x11cf…b6a3)    
node-1  | 2024-12-17T14:45:38.168608Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575384 (0x7ba7…a126), finalized #483395 (0xc600…88f1), ⬇ 415.5kiB/s ⬆ 195.0kiB/s    
node-1  | 2024-12-17T14:45:38.335080Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0x85e1…68ee)    
node-1  | 2024-12-17T14:45:39.226313Z  INFO Consensus: substrate: 🏆 Imported #575385 (0x7ba7…a126 → 0xe95d…4ab1)    
node-1  | 2024-12-17T14:45:40.495144Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0xb7d4…dd07)    
node-1  | 2024-12-17T14:45:41.248946Z  INFO Consensus: substrate: 🆕 Imported #575379 (0xb7d4…dd07 → 0xa490…9cba)    
node-1  | 2024-12-17T14:45:42.596078Z  INFO Consensus: substrate: 🏆 Imported #575386 (0xe95d…4ab1 → 0x50c3…d9db)    
node-1  | 2024-12-17T14:45:43.168999Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575386 (0x50c3…d9db), finalized #483395 (0xc600…88f1), ⬇ 211.1kiB/s ⬆ 163.2kiB/s    
node-1  | 2024-12-17T14:45:48.169407Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575386 (0x50c3…d9db), finalized #483395 (0xc600…88f1), ⬇ 25.0kiB/s ⬆ 247.8kiB/s    
node-1  | 2024-12-17T14:45:49.227649Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0xacf9…53d8)    
node-1  | 2024-12-17T14:45:50.689503Z  INFO Consensus: substrate: 🏆 Imported #575387 (0x50c3…d9db → 0x10a6…6d4c)    
node-1  | 2024-12-17T14:45:53.169864Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575387 (0x10a6…6d4c), finalized #483395 (0xc600…88f1), ⬇ 123.6kiB/s ⬆ 272.4kiB/s    
node-1  | 2024-12-17T14:45:53.618600Z  INFO Consensus: substrate: 🏆 Imported #575388 (0x10a6…6d4c → 0x55e3…592a)    
node-1  | 2024-12-17T14:45:57.588976Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0xbbc7…1520)    
node-1  | 2024-12-17T14:45:58.170229Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575388 (0x55e3…592a), finalized #483395 (0xc600…88f1), ⬇ 98.8kiB/s ⬆ 96.8kiB/s    
node-1  | 2024-12-17T14:45:58.485960Z  INFO Consensus: substrate: 🆕 Imported #575378 (0xfc18…d6c2 → 0xfd31…5276)    
node-1  | 2024-12-17T14:46:03.170790Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575388 (0x55e3…592a), finalized #483395 (0xc600…88f1), ⬇ 126.2kiB/s ⬆ 97.6kiB/s    
node-1  | 2024-12-17T14:46:03.216616Z  INFO Consensus: substrate: 🏆 Imported #575389 (0x55e3…592a → 0x7c07…ceab)    
node-1  | 2024-12-17T14:46:08.171262Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575389 (0x7c07…ceab), finalized #483395 (0xc600…88f1), ⬇ 42.0kiB/s ⬆ 65.4kiB/s    
node-1  | 2024-12-17T14:46:11.572369Z  INFO Consensus: substrate: 🏆 Imported #575390 (0x7c07…ceab → 0x2519…0a63)    
node-1  | 2024-12-17T14:46:12.621689Z  INFO Consensus: substrate: 🏆 Imported #575391 (0x2519…0a63 → 0x5e87…364a)    
node-1  | 2024-12-17T14:46:13.171456Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575391 (0x5e87…364a), finalized #483395 (0xc600…88f1), ⬇ 39.8kiB/s ⬆ 65.8kiB/s    
node-1  | 2024-12-17T14:46:18.171720Z  INFO Consensus: substrate: 💤 Idle (40 peers), best: #575391 (0x5e87…364a), finalized #483395 (0xc600…88f1), ⬇ 16.9kiB/s ⬆ 24.4kiB/s    

Warnings are not important and not happen every time, but pauses in block production for a few minutes do, which is a bug.

The latest observation is that there is a 100% CPU usage during this time (meaning a single core), which likely indicates the problem not in the archiving itself, but likely in the block finalization code of Substrate (that was optimized substantially, but still not exactly ideal).

Further investigation is needed and likely upstream work in Substrate to either optimize its finalization code even further (parallelizing would bring immediate benefits if possible), while #2114 will be the proper solution because it'll allow us to stop finalizing tens of thousands of blocks at once.