IntersectMBO / IntersectMBO/cardano-node-tests
measure time spent in each phase during node start
- Dominant language
- Python
- Stars
- 59
- Forks
- 28
- Avg merge
- 2h 30m
- Merged PRs (30d)
- 62
Description
measure the node start time per stage:
- `Chain DB`
- `Immutable DB`
- `Volatile DB`
- `Ledger DB`
**Scenarios**:
**1.**
- (have the node fully synced with tagNo1)
- clean stop --> stop the node using `killall -SIGINT cardano-node`
- start the node using the same tagNo1 and measure the time spend in each of the 3 phases + total time until the node is fully started
**2.**
- (have the node fully synced with tagNo1)
- clean stop --> stop the node using `killall -SIGINT cardano-node`
- start the node using tagNo2 and measure the time spend in each of the 3 phases + total time until the node is fully started
**3.**
- (stop the node during the `Immutable DB` phase using `killall -SIGINT cardano-node`)
- start the node and measure the time spend in each of the 3 phases + total time until the node is fully started
**4.**
- (stop the node during the `Volatile DB` phase using `killall -SIGINT cardano-node`)
- start the node and measure the time spend in each of the 3 phases + total time until the node is fully started
**5.**
- (stop the node during the `Ledger DB` phase using `killall -SIGINT cardano-node`)
- start the node and measure the time spend in each of the 3 phases + total time until the node is fully started
```
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:29:20.85 UTC] Started opening Chain DB
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:29:20.85 UTC] Started opening Immutable DB
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:29:20.97 UTC] Validating chunk no. 2504 out of 2504. Progress: 99.96%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:29:21.09 UTC] Validated chunk no. 2504 out of 2504. Progress: 100.00%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:29:21.09 UTC] Found a valid last location at chunk 2504 with tip 708c365fdb6c146acc50bfaf8ca59fa34035a8d9c2d0f8a0e170b9f98aa69873@54086732.
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:29:21.09 UTC] Opened imm db with immutable tip at 708c365fdb6c146acc50bfaf8ca59fa34035a8d9c2d0f8a0e170b9f98aa69873 at slot 54086732 and chunk 2504
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:29:21.09 UTC] Started opening Volatile DB
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:29:30.11 UTC] Opened vol db
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:29:30.11 UTC] Started opening Ledger DB
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:32:23.31 UTC] Replaying ledger from snapshot at 140c1227031439a1441951e110059a7fb646ab14609ea2f5a226c26307ac1fed at slot 54082830
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:32:23.37 UTC] Replayed block: slot 54082842 out of 54086732. Progress: 0.31%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:32:31.90 UTC] Replayed block: slot 54086392 out of 54086732. Progress: 91.29%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:32:39.52 UTC] Opened lgr db
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:32:39.52 UTC] Started initial chain selection
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:32:40.07 UTC] Pushing ledger state for block 7d9b7375e2857695278851e0c0a7b87b8ee0dbd45eef7a3605c1b9a66e41ae93 at slot 54086744. Progress: 0.00%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:33:12.10 UTC] before next, messages elided = 54086745
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:33:12.10 UTC] Pushing ledger state for block 6f4116ecaf0ff9b1377ab607b8240d437cc9bb6fa3b818b2a41bc4f67c85553c at slot 54096736. Progress: 21.77%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:33:12.10 UTC] Pushing ledger state for block bec48d38cbb593571aff74dbef17b4779aed56e4a580d03252507c9890df0bf6 at slot 54096747. Progress: 21.80%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:33:12.17 UTC] Pushing ledger state for block 1d09c4c067286d5572d709b4b83b99eff0bed0a1f2840cd625e7d162027853a9 at slot 54096750. Progress: 21.80%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:33:44.10 UTC] before next, messages elided = 54096847
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:33:44.10 UTC] Pushing ledger state for block 0c5d3d0d373f4fbef5eac9a615ef2e9dbe13e4038da0eb325c3f164d897ad4ac at slot 54106832. Progress: 43.77%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:33:44.10 UTC] Pushing ledger state for block 35c003cebefdc43d0794b59ffc2561b0fd491f3235de7ca05d1053e99b6151a9 at slot 54106864. Progress: 43.84%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:33:44.17 UTC] Pushing ledger state for block 3cd7281deccffb9de2653d0be567062743c52b4fb520ed278c1ac530bc6b4428 at slot 54106866. Progress: 43.84%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:34:16.47 UTC] before next, messages elided = 54106901
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:34:16.47 UTC] Pushing ledger state for block 146d1cfa442b8c3f604f365a311434f929d2efead9163332c0a46d8952d7ecbb at slot 54116884. Progress: 65.67%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:34:16.47 UTC] Pushing ledger state for block 792e880c7c4c52c0b22a3ebcd667923290ab1d402ce0f7ea96f945db64c3c796 at slot 54116908. Progress: 65.72%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:34:16.54 UTC] Pushing ledger state for block ae770df77e5f7e2841290e2f9d2faa982768ff02abaaaf009d24f426f905b246 at slot 54116923. Progress: 65.76%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:34:54.25 UTC] before next, messages elided = 54116967
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:34:54.25 UTC] Pushing ledger state for block 1ef5aac2c084751ca718a5a1f7c416658e6511e4bef5176073e8b24911bdad76 at slot 54126944. Progress: 87.59%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:34:54.25 UTC] Pushing ledger state for block d657a70e587b57b9e5e923e050367c49f6ca35a0f761a2d2c3473160eda35ba4 at slot 54126973. Progress: 87.65%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:34:54.37 UTC] Pushing ledger state for block ea1158ca93bfb2eaef6d180f947e26cfb68e2d29b5d2bdf0ea96221b0ff8f21b at slot 54126999. Progress: 87.71%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:35:14.18 UTC] before next, messages elided = 54127008
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:35:14.18 UTC] Pushing ledger state for block 7760c1b38ccc7d85cf916a6bc0a7c7f26b3420c5c1e9b08f357c0e460da0f42e at slot 54132639. Progress: 100.00%
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:35:14.18 UTC] Valid candidate at tip 7d9b7375e2857695278851e0c0a7b87b8ee0dbd45eef7a3605c1b9a66e41ae93 at slot 54086744
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:35:14.18 UTC] Initial chain selected
[34m[ip-172-3:cardano.node.ChainDB:Info:5][0m [2022-03-02 07:35:14.18 UTC] Opened db with immutable tip at 708c365fdb6c146acc50bfaf8ca59fa34035a8d9c2d0f8a0e170b9f98aa69873 at slot 54086732 and tip 7760c1b38ccc7d85cf916a6bc0a7c7f26b3420c5c1e9b08f357c0e460da0f42e at slot 54132639
[35m[ip-172-3:cardano.node.DnsSubscription:Notice:416][0m [2022-03-02 07:35:14.20 UTC] Domain: "relays-new.cardano-mainnet.iohk.io" Connection Attempt Start, destination 3.23.246.240:3001
[35m[ip-172-3:cardano.node.DnsSubscription:Notice:416][0m [2022-03-02 07:35:14.20 UTC] Domain: "relays-new.cardano-mainnet.iohk.io" Connection Attempt End, destination 3.23.246.240:3001 outcome: ConnectSuccess
[35m[ip-172-3:cardano.node.DnsSubscription:Notice:430][0m [2022-03-02 07:35:14.22 UTC] Domain: "relays-new.cardano-mainnet.iohk.io" Connection Attempt Start, destination 18.157.126.47:3001
[35m[ip-172-3:cardano.node.DnsSubscription:Notice:431][0m [2022-03-02 07:35:14.25 UTC] Domain: "relays-new.cardano-mainnet.iohk.io" Connection Attempt Start, destination 18.158.188.21:3001
[35m[ip-172-3:cardano.node.DnsSubscription:Notice:432][0m [2022-03-02 07:35:14.27 UTC] Domain: "relays-new.cardano-mainnet.iohk.io" Connection Attempt Start, destination 3.112.168.85:3001
[35m[ip-172-3:cardano.node.DnsSubscription:Notice:433][0m [2022-03-02 07:35:14.30 UTC] Domain: "relays-new.cardano-mainnet.iohk.io" Connection Attempt Start, destination 3.13.80.218:3001
[35m[ip-172-3:cardano.node.DnsSubscription:Notice:433][0m [2022-03-02 07:35:14.30 UTC] Domain: "relays-new.cardano-mainnet.iohk.io" Connection Attempt End, destination 3.13.80.218:3001 outcome: ConnectSuccessLast
[35m[ip-172-3:cardano.node.ErrorPolicy:Notice:400][0m [2022-03-02 07:35:14.30 UTC] IP 18.157.126.47:3001 ErrorPolicySuspendConsumer (Just (ConnectionExceptionTrace (SubscriberError {seType = SubscriberParallelConnectionCancelled, seMessage = "Parallel connection cancelled", seStack = []}))) 1s
[35m[ip-172-3:cardano.node.ErrorPolicy:Notice:400][0m [2022-03-02 07:35:14.30 UTC] IP 18.158.188.21:3001 ErrorPolicySuspendConsumer (Just (ConnectionExceptionTrace (SubscriberError {seType = SubscriberParallelConnectionCancelled, seMessage = "Parallel connection cancelled", seStack = []}))) 1s
[35m[ip-172-3:cardano.node.ErrorPolicy:Notice:400][0m [2022-03-02 07:35:14.30 UTC] IP 3.112.168.85:3001 ErrorPolicySuspendConsumer (Just (ConnectionExceptionTrace (SubscriberError {seType = SubscriberParallelConnectionCancelled, seMessage = "Parallel connection cancelled", seStack = []}))) 1s
[35m[ip-172-3:cardano.node.ChainDB:Notice:382][0m [2022-03-02 07:35:14.44 UTC] Chain extended, new tip: b5a12910959c5b397aa53977269843d91e2a634b769b551633d3e1525d3b0101 at slot 54132765
[35m[ip-172-3:cardano.node.ChainDB:Notice:382][0m [2022-03-02 07:35:15.77 UTC] Chain extended, new tip: d06ac1d4f18f56eb74f02b6a2028526b0900b97248ed1d3b15fc9cc6cce1efba at slot 54133196
[35m[ip-172-3:cardano.node.ChainDB:Notice:382][0m [2022-03-02 07:35:17.05 UTC] Chain extended, new tip: e809ee4a5812055f52e902a4611ec79fd9b4cc9ccd6f33f4325fc754a2f9a9bd at slot 54133355
```
Contributor guide
Assessment
This issue has not been assessed yet.