What is happening between `Is collating: yes` and ` Local node identity is:...` or why is it taking so long time to restart syncing of a crashed node?

Question

I'm trying to sync a parachain node from scratch with a client upgraded to polkadot0.9.37

I have experienced crashes and restarts after a few hours and with every subsequent restart it seems to take longer to restart the node.

In this log I found a gap for several hours

2023-03-02 10:53:18.588 INFO main sc_cli::runner: Nodle Parachain Collator 2023-03-02 10:53:18.588 INFO main sc_cli::runner: ✌️ version 2.0.26-5632a16685e 2023-03-02 10:53:18.588 INFO main sc_cli::runner: ❤️ by Nodle <[email protected]>:Parity Technologies <[email protected]>, 2020-2023 2023-03-02 10:53:18.588 INFO main sc_cli::runner: 📋 Chain specification: Nodle Parachain 2023-03-02 10:53:18.588 INFO main sc_cli::runner: 🏷 Node name: fretful-rings-3704 2023-03-02 10:53:18.588 INFO main sc_cli::runner: 👤 Role: AUTHORITY 2023-03-02 10:53:18.588 INFO main sc_cli::runner: 💾 Database: RocksDb at .testdrivedata-master/chains/para_eden/db/full 2023-03-02 10:53:18.588 INFO main sc_cli::runner: ⛓ Native runtime: nodle-para-17 (nodle-para-0.tx6.au1) 2023-03-02 10:53:24.642 INFO main nodle_parachain::command: Parachain id: Id(2026) 2023-03-02 10:53:24.642 INFO main nodle_parachain::command: Parachain Account: 5Ec4AhPa9Z5gxN6u3dL6bydrbCkwpiaWuvanrZKegBPQUXMk 2023-03-02 10:53:24.642 INFO main nodle_parachain::command: Parachain genesis state: 0x00000000000000000000000000000000000000000000000000000000000000000041acf2b680686c9cb62433905459d97c5e820e1674c08e7ad66d2a307305634003170a2e7597b7b7e3d84c05391d139a62b157e78786d8c082f29dcf4c11131400 2023-03-02 10:53:24.642 INFO main nodle_parachain::command: Is collating: yes 2023-03-02 14:59:18.987 INFO main sub-libp2p: [Relaychain] 🏷 Local node identity is: 12D3KooWHxy6acp5PmoatkbudPqGG9PVQdxKbvkiCgaPJTtdR1MW 2023-03-02 14:59:18.991 WARN main sub-libp2p: [Relaychain] Can't listen on /ip6/::/tcp/30334/ws because: Other(Custom { kind: Other, error: Other(A(A(A(A(Transport(A(Transport(Os { code: 98, kind: AddrInUse, message: "Address already in use" })))))))) }) 2023-03-02 14:59:18.991 WARN main sub-libp2p: [Relaychain] Can't listen on /ip4/0.0.0.0/tcp/30334/ws because: Other(Custom { kind: Other, error: Other(A(A(A(A(Transport(A(Transport(Os { code: 98, kind: AddrInUse, message: "Address already in use" })))))))) }) 2023-03-02 14:59:20.591 INFO main sc_sysinfo: [Relaychain] 💻 Operating system: linux 2023-03-02 14:59:20.591 INFO main sc_sysinfo: [Relaychain] 💻 CPU architecture: x86_64 2023-03-02 14:59:20.591 INFO main sc_sysinfo: [Relaychain] 💻 Target environment: gnu 2023-03-02 14:59:20.591 INFO main sc_sysinfo: [Relaychain] 💻 CPU: 11th Gen Intel(R) Core(TM) i7-11700 @ 2.50GHz 2023-03-02 14:59:20.591 INFO main sc_sysinfo: [Relaychain] 💻 CPU cores: 8 2023-03-02 14:59:20.591 INFO main sc_sysinfo: [Relaychain] 💻 Memory: 63923MB 2023-03-02 14:59:20.591 INFO main sc_sysinfo: [Relaychain] 💻 Kernel: 5.14.0-1057-oem 2023-03-02 14:59:20.591 INFO main sc_sysinfo: [Relaychain] 💻 Linux distribution: Linux Mint 20.2 2023-03-02 14:59:20.591 INFO main sc_sysinfo: [Relaychain] 💻 Virtual machine: no 2023-03-02 14:59:20.591 INFO main sc_service::builder: [Relaychain] 📦 Highest known block at #9710531 2023-03-02 14:59:20.595 INFO main sc_rpc_server: [Relaychain] Running JSON-RPC HTTP server: addr=127.0.0.1:42981, allowed origins=["http://localhost:*", "http://127.0.0.1:*", "https://localhost:*", "https://127.0.0.1:*", "https://polkadot.js.org"] 2023-03-02 14:59:20.596 INFO main sc_rpc_server: [Relaychain] Running JSON-RPC WS server: addr=127.0.0.1:40447, allowed origins=["http://localhost:*", "http://127.0.0.1:*", "https://localhost:*", "https://127.0.0.1:*", "https://polkadot.js.org"] 2023-03-02 14:59:20.596 INFO main sc_sysinfo: [Relaychain] 🏁 CPU score: 988.39 MiBs 2023-03-02 14:59:20.596 INFO main sc_sysinfo: [Relaychain] 🏁 Memory score: 11.40 GiBs 2023-03-02 14:59:20.596 INFO main sc_sysinfo: [Relaychain] 🏁 Disk score (seq. writes): 53.57 MiBs 2023-03-02 14:59:20.596 INFO main sc_sysinfo: [Relaychain] 🏁 Disk score (rand. writes): 29.16 MiBs

What is it doing between 10:53:24.642 and 14:59:18.987 ? In the earliest logs I captured this gap was only a few seconds.

Please post the cli flags you are using.

bkchr
– bkchr ♦

2023-03-03 05:54:50 +00:00
Commented Mar 3, 2023 at 5:54 — bkchr
– bkchr ♦, Commented Mar 3, 2023 at 5:54

aurexav · Accepted Answer · 2023-03-02 06:57:48Z

It looks like you are using a pretty old HHD.

It takes a long time to load the data.

2023-03-02 14:59:20.596 INFO main sc_sysinfo: [Relaychain] 🏁 Disk score (seq. writes): 53.57 MiBs 2023-03-02 14:59:20.596 INFO main sc_sysinfo: [Relaychain] 🏁 Disk score (rand. writes): 29.16 MiBs

I'm using SSD. And It still takes a few seconds on my side.

2023-03-02 14:56:14 [Relaychain] 🏁 Disk score (seq. writes): 9.70 GiBs 2023-03-02 14:56:14 [Relaychain] 🏁 Disk score (rand. writes): 3.49 GiBs

So, I think the only option is upgrading your hardware.

There are some other work going on on this computer. And I see variations from 1G down to 20 M. But the question is what is happening when there are no prints for several hours. — Simson
– Simson, Commented Mar 2, 2023 at 7:17
AFAIK, it was loading the latest state from the DB. You can set RUST_LOG=db. — aurexav
– aurexav ♦, Commented Mar 2, 2023 at 7:53

Stack Exchange Network

What is happening between `Is collating: yes` and ` Local node identity is:...` or why is it taking so long time to restart syncing of a crashed node?

1 Answer 1

Hot Network Questions