irmin
irmin copied to clipboard
Published
20 hours ago •
mirage
mirage
irmin-pack: inverstigate performance regression with GC
Running the lib_context benchmarks on the trace with the first 2 months of hanghzou (so what we use for the release benchmarks). The Gc is called every cycle (8100 blocks), it simulates the tezos scenarios for a bootstrap. For this run, gc was called 17 times.
| | 3.2-a | 3.2-b | 3.3.1-a | 3.3.1-b | good-gc-a | good-gc-b
| -- | -- | -- | -- | -- | -- | --
| -- main metrics -- | | | | | |
| CPU time elapsed | 164m49s | 165m36s 100% | 162m50s 99% | 163m50s 99% | 201m20s 122% | 200m53s 122%
| Wall time elapsed | 227m49s | 228m19s 100% | 220m18s 97% | 221m17s 97% | 205m50s 90% | 204m02s 90%
| TZ-transactions per sec | 1599.995 | 1592.411 100% | 1619.583 101% | 1609.597 101% | 1309.786 82% | 1312.774 82%
| TZ-operations per sec | 2616.083 | 2603.684 100% | 2648.112 101% | 2631.783 101% | 2141.575 82% | 2146.461 82%
| Context.add per sec | 21324.673 | 21223.599 100% | 21585.751 101% | 21452.650 101% | 17456.776 82% | 17496.602 82%
| tail latency (1) | 0.248 s | 0.191 s 77% | 0.574 s 231% | 0.438 s 176% | 2.873 s 12x | 2.881 s 12x
| | | | | | |
| -- resource usage -- | | | | | |
| disk IO (total) | | | | | |
| IOPS (op/sec) | 316_747 | 315_245 100% | 320_663 101% | 318_686 101% | 673_858 213% | 675_387 213%
| throughput (bytes/sec) | 98.877 M | 98.409 M 100% | 100.089 M 101% | 99.472 M 101% | 42.916 M 43% | 43.014 M 44%
| total (bytes) | 977.810 G | 977.810 G 100% | 977.822 G 100% | 977.822 G 100% | 518.442 G 53% | 518.441 G 53%
| disk IO (read) | | | | | |
| IOPS (op/sec) | 316_638 | 315_137 100% | 320_514 101% | 318_538 101% | 673_786 213% | 675_314 213%
| throughput (bytes/sec) | 93.300 M | 92.858 M 100% | 94.443 M 101% | 93.860 M 101% | 38.174 M 41% | 38.261 M 41%
| total (bytes) | 922.661 G | 922.661 G 100% | 922.661 G 100% | 922.661 G 100% | 461.158 G 50% | 461.154 G 50%
| disk IO (write) | | | | | |
| IOPS (op/sec) | 109 | 108 100% | 149 137% | 148 136% | 72 66% | 72 66%
| throughput (bytes/sec) | 5.577 M | 5.550 M 100% | 5.646 M 101% | 5.611 M 101% | 4.742 M 85% | 4.753 M 85%
| total (bytes) | 55.149 G | 55.149 G 100% | 55.161 G 100% | 55.161 G 100% | 57.285 G 104% | 57.287 G 104%
| | | | | | |
| max memory usage (bytes) | 0.402 G | 0.395 G 98% | 0.441 G 110% | 0.443 G 110% | 1.413 G 352% | 1.457 G 363%
| mean CPU usage | 72% | 73% | 74% | 74% | 98% | 98%
The worrisome part is the tail-latency - on average commits are faster, but the max ones are of almost 3s:
| | | cumu | share | min | max | avg
| | | | | | |
| commit duration (s) | 3.2-a | 51min8s | 22% | 1.820 ms | 0.248 s | 21.165 ms
| | 3.2-b | 50min57s 100% | 22% | 1.817 ms 100% | 0.191 s 77% | 21.087 ms 100%
| | 3.3.1-a | 49min32s 97% | 22% | 1.970 ms 108% | 0.574 s 231% | 20.502 ms 97%
| | 3.3.1-b | 49min32s 97% | 22% | 1.993 ms 110% | 0.438 s 176% | 20.502 ms 97%
| | good-gc-a | 38min30s 75% | 19% | 1.624 ms 89% | 2.873 s 12x | 15.934 ms 75%
| | good-gc-b | 38min20s 75% | 19% | 1.583 ms 87% | 2.881 s 12x | 15.862 ms 75%
The logs also report two times for the GC - the start_gc and finalise_gc. It is the finalise_gc that is the culprit:
Gc ended on commit CoWBpkAvV1xfJcve67PV7ZB2YNTfBKQ286bEV7A2f4UW6cvKznsp, it took 799.7337ms
Gc ended on commit CoW3kCnEH2ENMk6tsLaJNKVm4Zign3sHSLcqbjWU1TCTG5wH31JU, it took 828.0304ms
...
Gc ended on commit CoUxQyRdgJ1K8ETvNuA8VuMkRHGhwCgeER5NSdQTmeAsVqwK4qQo, it took 2813.7762ms
Gc ended on commit CoWX7eSo2E1iod3kcRzQ2HWGyMWi73UUqvmHZq9nsDzVAyNsRxWj, it took 2871.5800ms
which is probably due to transferring the latest newies, but not sure. However, if the gc is run at a slower pace (not for bootstrapping) then maybe its possible that this finalise_gc does not take so long, but either way, i think this is something we need to look into.
When the worker runs, it creates a new prefix file (sparse file) and a new suffix file.
The new suffix file is created by copying directly from the current suffix file (from some chosen offset to the end): the worker asks for the length of the suffix and then copies the bytes from the offset to the end of the current suffix, into the new suffix.
But, during this copy, the suffix is "live" and being written to by the main process. If the copy is long (and it is with Tezos), the current suffix may grow substantially. So, the worker should repeatedly copy from the current suffix, until either there are very few bytes left (if any) to copy (or until some small finite limit on the number of copies is reached - say 7 iterations to be safe... we don't want an infinite loop where the worker and the main process continue in parallel forever).
Now, it is always the case that after the worker terminates, the current suffix is still live, so potentially updated, so the next suffix (that was just created by the worker) is then out of date. So the main process must also copy any extra data at the end of the current suffix to the next suffix, before switching over.
In the current code, the worker copies data from the current suffix to the new suffix in this file:
https://github.com/mirage/irmin/blob/main/src/irmin-pack/unix/gc.ml
The copy happens at step 7 "transfer to the next suffix". But from the code it looks like the copy is performed only once.
What this means is that, when the worker terminates and transfers back to the main process, the main process might have to copy a lot more data than if the "step 7 transfer" had been repeated. This is likely a source of the slow down. (I expect there are other sources as well, which I will come back to tomorrow.)
This is the main unknown for the release - we need to at least understand what is happening. @tomjridge's current assumption is that is related to copying the suffix in the main process that takes time (as it's a lot of data). One possible fix would be to make the child process do more work: we might need a loop in the child to copy data if there were concurrent writes in the parent (if the max offset has changed since the data copying has started).
In #1974 it was reported that reads are greatly increased (irmin main vs 3.3.1). Irmin main branch is presumably similar to good-gc. But in the stats reported here, the reads seem similar (good-gc vs 3.3.1). So these stats are at odds with those in #1974.
Another possible cause of slowdown: when the main process switches to the new prefix (sparse file) it has to load a mapping file. Previously this was loaded very quickly, but the new code may be slower.
Another possibility: suppose at the end of a commit, we issue an fsync (I don't know whether we do or not - likely we don't, but let's assume we do...), and suppose the filesystem executed an fsync by flushing all filesystem buffers (not just those related to the fsync'ed file... this is quite common in filesystem impls), and suppose there was (concurrently) a large copy in progress (the GC copying the suffix file to make the new suffix file); then the fsync would take much longer (compared to the scenario where there was no GC running). So the overall time for the commit would be longer.
I don't think this possibility is likely. I'm just recording it here so I don't forget to investigate it.
The finalise_gc is taking up to 3s, leading to commits of 3s as well. There are 4 major steps in finalise_gc, I plotted the time each takes (I run the lib_context benchmarks with some added timers and the datapoints are here).
It is clearly swap_and_purge that is taking the longest. I'll rerun with more timers in the swap, but it is probably loading the mapping file in memory that is the longest.
A zoom in for the transfer remaining newies by the main process (this is without https://github.com/mirage/irmin/pull/1986).
So in this benchmarks at least, not doing a transfer loop in the child is not costly - the main process spends less than 100 ms for the transfer. It still might be useful to have the transfer loop in the child though, as there is a correlation between newies left and time to transfer.
Now that the mapping doesn't need to be read at finalise time, unlink dominates the finalisation time
(generated using https://github.com/tarides/irmin-scratch/blob/main/scripts/issue1959/script.py)
<details>
<summary> Setups </summary>
| | aaa
| -- | --
| hostname | bench-gc
| os type | Unix
| big endian | false
| runtime params (no gc) | b=1,H=0,p=0,t=0,v=0,w=1,W=0
| backend type | native
| ocaml version | 4.14.0
| word size | 64 bits
| Start Time | 2022/08/04 14:26:40 (GMT)
| Store Type | pack
| gc.minor_heap_size | 262144
| gc.major_heap_increment | 15
| gc.space_overhead | 120
| gc.verbose | 0
| gc.max_overhead | 500
| gc.stack_limit | 0
| gc.allocation_policy | 2
| gc.window_size | 1
| gc.custom_major_ratio | 44
| gc.custom_minor_ratio | 100
| gc.custom_minor_max_size | 8192
</details>
| | aaa
| -- | --
| -- main metrics -- |
| CPU time elapsed | 208m34s
| Wall time elapsed | 216m38s
| TZ-transactions per sec | 1264.342
| TZ-operations per sec | 2067.272
| Context.add per sec | 16851.107
| tail latency (1) | 1.204 s
| |
| -- resource usage -- |
| disk IO (total) |
| IOPS (op/sec) | 227_460
| throughput (bytes/sec) | 17.472 M
| total (bytes) | 218.657 G
| disk IO (read) |
| IOPS (op/sec) | 227_390
| throughput (bytes/sec) | 12.849 M
| total (bytes) | 160.803 G
| disk IO (write) |
| IOPS (op/sec) | 70
| throughput (bytes/sec) | 4.623 M
| total (bytes) | 57.854 G
| |
| max memory usage (bytes) | 0.617 G
| mean CPU usage | 96%
- (1) Longest Context.commit.
- The "per sec" stats are calculated over CPU time.
- "max memory usage" is the max size of the RSS memory allocated.
- "mean CPU usage" is inexact.
-- global --
| | total | min per block | max per block | avg per block | avg per sec
| | | | | |
| tree.empty count | 0 | 0 | 0 | 0 | 0
| tree.of_raw count | 0 | 0 | 0 | 0 | 0
| tree.of_value count | 0 | 0 | 0 | 0 | 0
| tree.mem count | 0 | 0 | 0 | 0 | 0
| tree.mem_tree count | 0 | 0 | 0 | 0 | 0
| tree.find count | 0 | 0 | 0 | 0 | 0
| tree.is_empty count | 0 | 0 | 0 | 0 | 0
| tree.kind count | 12_439 | 0 | 813 | 0.086 | 0.957
| tree.hash count | 0 | 0 | 0 | 0 | 0
| tree.equal count | 0 | 0 | 0 | 0 | 0
| tree.to_value count | 215 | 0 | 215 | 0.001 | 0.017
| tree.clear count | 0 | 0 | 0 | 0 | 0
| tree.find_tree count | 0 | 0 | 0 | 0 | 0
| tree.add count | 0 | 0 | 0 | 0 | 0
| tree.add_tree count | 0 | 0 | 0 | 0 | 0
| tree.remove count | 0 | 0 | 0 | 0 | 0
| tree.fold count | 37 | 0 | 3 | 0.000 | 0.003
| find_tree count | 49_697 | 0 | 21 | 0.343 | 3.823
| fold count | 0 | 0 | 0 | 0 | 0
| add_tree count | 49_697 | 0 | 21 | 0.343 | 3.823
| mem count | 221_000_542 | 83 | 40_312 | 1524.142 | 17002.647
| mem_tree count | 47_161_435 | 280 | 345 | 325.251 | 3628.359
| find count | 619_355_216 | 1_402 | 178_076 | 4271.415 | 47650.010
| get_protocol count | 579_829 | 3 | 4 | 3.999 | 44.609
| hash count | 0 | 0 | 0 | 0 | 0
| find_predecessor_block_metadata_hash count | 0 | 0 | 0 | 0 | 0
| find_predecessor_ops_metadata_hash count | 0 | 0 | 0 | 0 | 0
| get_test_chain count | 145_000 | 1 | 1 | 1.000 | 11.156
| exists count | 0 | 0 | 0 | 0 | 0
| retrieve_commit_info count | 0 | 0 | 0 | 0 | 0
| add count | 210_882_505 | 215 | 86_856 | 1454.362 | 16224.217
| remove count | 2_500_253 | 0 | 1_935 | 17.243 | 192.357
| add_protocol count | 0 | 0 | 0 | 0 | 0
| add_predecessor_block_metadata_hash count | 145_000 | 1 | 1 | 1.000 | 11.156
| add_predecessor_ops_metadata_hash count | 145_000 | 1 | 1 | 1.000 | 11.156
| add_test_chain count | 0 | 0 | 0 | 0 | 0
| remove_test_chain count | 0 | 0 | 0 | 0 | 0
| fork_test_chain count | 0 | 0 | 0 | 0 | 0
| checkout count | 144_829 | 0 | 1 | 0.999 | 11.142
| clear_test_chain count | 0 | 0 | 0 | 0 | 0
| init count | 1 | 0 | 1 | 0.000 | 0.000
| restore_context count | 0 | 0 | 0 | 0 | 0
| commit count | 145_000 | 1 | 1 | 1.000 | 11.156
| close count | 0 | 0 | 0 | 0 | 0
| dump_context count | 0 | 0 | 0 | 0 | 0
| | | | | |
| Disk bytes read | 160.803 G | 0.035 M | 25.371 M | 1.109 M | 12.371 M
| Disk bytes written | 57.854 G | 0.087 M | 24.349 M | 0.399 M | 4.451 M
| Disk bytes both | 218.657 G | 0.325 M | 49.720 M | 1.508 M | 16.822 M
| | | | | |
| Disk reads | 2845.668 M | 776 | 256_758 | 19625.298 | 218931.106
| Disk writes | 0.872 M | 4 | 31 | 6.015 | 67.105
| Disk both | 2846.541 M | 780 | 256_770 | 19631.314 | 218998.211
| | | | | |
| pack.finds_total | 789.815 M | 1_942 | 127_940 | 5446.999 | 60764.300
| pack.finds_from_staging | 0.000 M | 0 | 18 | 0.002 | 0.027
| pack.finds_from_lru | 575.815 M | 1_332 | 84_105 | 3971.140 | 44300.275
| pack.finds_from_pack_direct | 213.999 M | 0 | 45_018 | 1475.856 | 16463.998
| pack.finds_from_pack_indexed | 0 | 0 | 0 | 0 | 0
| pack.cache_misses | 213.999 M | 0 | 45_018 | 1475.856 | 16463.998
| pack.appended_hashes | 0 | 0 | 0 | 0 | 0
| pack.appended_offsets | 2904.872 M | 3_458 | 161_110 | 20033.601 | 223485.951
| pack.inode_add | 123.638 M | 211 | 15_137 | 852.676 | 9512.078
| pack.inode_remove | 1.168 M | 0 | 1_927 | 8.057 | 89.880
| pack.inode_of_seq | 5.228 M | 0 | 1_737 | 36.052 | 402.183
| pack.inode_of_raw | 253.585 M | 566 | 10_701 | 1748.860 | 19509.503
| pack.inode_rec_add | 243.796 M | 350 | 30_487 | 1681.354 | 18756.434
| pack.inode_rec_remove | 2.204 M | 0 | 7_538 | 15.197 | 169.534
| pack.inode_to_binv | 288.697 M | 354 | 36_565 | 1991.015 | 22210.876
| pack.inode_decode_bin | 174.371 M | 0 | 34_627 | 1202.561 | 13415.239
| pack.inode_encode_bin | 182.367 M | 229 | 34_387 | 1257.704 | 14030.384
| | | | | |
| tree.contents_hash | 96.209 M | 172 | 7_991 | 663.511 | 7401.833
| tree.contents_find | 274.968 M | 575 | 89_556 | 1896.329 | 21154.603
| tree.contents_add | 71.018 M | 106 | 7_791 | 489.781 | 5463.775
| tree.contents_mem | 0 | 0 | 0 | 0 | 0
| tree.node_hash | 0 | 0 | 0 | 0 | 0
| tree.node_mem | 0 | 0 | 0 | 0 | 0
| tree.node_index | 0 | 0 | 0 | 0 | 0
| tree.node_add | 63.432 M | 105 | 7_611 | 437.460 | 4880.105
| tree.node_find | 253.585 M | 566 | 10_701 | 1748.860 | 19509.503
| tree.node_val_v | 5.228 M | 0 | 1_737 | 36.052 | 402.183
| tree.node_val_find | 0 | 0 | 0 | 0 | 0
| tree.node_val_list | 0.731 M | 1 | 388 | 5.041 | 56.240
| | | | | |
| index.cumu_data_bytes | 0 | 0 | 0 | 0 | 0
| | | | | |
| gc.minor_words allocated | 2554.190 G | 4.996 M | 415.153 M | 17.615 M | 196.506 M
| gc.major_words allocated | 211.196 G | 0.403 M | 26.971 M | 1.457 M | 16.248 M
| gc.minor_collections | 9.763 M | 19 | 1_586 | 67.329 | 751.094
| gc.major_collections | 0.036 M | 0 | 4 | 0.249 | 2.780
| | | | | |
| rusage.utime | 3h9min | 15.763 ms | 1.419 s | 78.479 ms | 0.875 s
| rusage.stime | 18min55s | 0 | 0.460 s | 7.828 ms | 87.322 ms
| rusage.maxrss | 0.617 G | 0 | 0.064 G | 0.000 G | 0.000 G
| rusage.minflt | 3.863 M | 0 | 37_682 | 26.638 | 297.166
| rusage.majflt | 37_698 | 0 | 2_236 | 0.260 | 2.900
| rusage.inblock | 194.216 M | 0 | 302_920 | 1339.422 | 14942.001
| rusage.oublock | 128.241 M | 200 | 47_704 | 884.422 | 9866.222
| rusage.nvcsw | 1.463 M | 0 | 2_613 | 10.091 | 112.567
| rusage.nivcsw | 0.045 M | 0 | 39 | 0.312 | 3.479
| | cumu | share | min | max | avg
| | | | | |
| block duration (s) | 3h36min | 100% | 20.789 ms | 2.410 s | 89.641 ms
| buildup duration (s) | 2h54min | 81% | 15.025 ms | 2.360 s | 72.186 ms
| commit duration (s) | 42min11s | 19% | 1.832 ms | 1.204 s | 17.455 ms
| | | | | |
| tree.empty duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.of_raw duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.of_value duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.mem duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.mem_tree duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.find duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.is_empty duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.kind duration (s) | 1.317 ms | 0% | 0.000 ms | 0.122 ms | 0.000 ms
| tree.hash duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.equal duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.to_value duration (s) | 0.326 ms | 0% | 0.000 ms | 0.244 ms | 0.002 ms
| tree.clear duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.find_tree duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.add duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.add_tree duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.remove duration (s) | 0 | 0 | n/a | n/a | n/a
| tree.fold duration (s) | 60.337 ms | 0% | 0.040 ms | 3.972 ms | 1.631 ms
| find_tree duration (s) | 79.390 ms | 0% | 0.000 ms | 0.659 ms | 0.002 ms
| fold duration (s) | 0 | 0 | n/a | n/a | n/a
| add_tree duration (s) | 5130.239 ms | 0% | 0.001 ms | 148.819 ms | 0.103 ms
| mem duration (s) | 2589988.681 ms | 20% | 0.000 ms | 479.171 ms | 0.012 ms
| mem_tree duration (s) | 99143.168 ms | 1% | 0.000 ms | 59.071 ms | 0.002 ms
| find duration (s) | 5289807.127 ms | 41% | 0.000 ms | 194.656 ms | 0.009 ms
| get_protocol duration (s) | 3455.414 ms | 0% | 0.000 ms | 11.712 ms | 0.006 ms
| hash duration (s) | 0 | 0 | n/a | n/a | n/a
| find_predecessor_block_metadata_hash duration (s) | 0 | 0 | n/a | n/a | n/a
| find_predecessor_ops_metadata_hash duration (s) | 0 | 0 | n/a | n/a | n/a
| get_test_chain duration (s) | 1253.819 ms | 0% | 0.003 ms | 17.192 ms | 0.009 ms
| exists duration (s) | 0 | 0 | n/a | n/a | n/a
| retrieve_commit_info duration (s) | 0 | 0 | n/a | n/a | n/a
| add duration (s) | 688050.422 ms | 5% | 0.000 ms | 40.412 ms | 0.003 ms
| remove duration (s) | 12549.384 ms | 0% | 0.000 ms | 4.943 ms | 0.005 ms
| add_protocol duration (s) | 0 | 0 | n/a | n/a | n/a
| add_predecessor_block_metadata_hash duration (s) | 1678.359 ms | 0% | 0.004 ms | 4.018 ms | 0.012 ms
| add_predecessor_ops_metadata_hash duration (s) | 1058.043 ms | 0% | 0.001 ms | 3.790 ms | 0.007 ms
| add_test_chain duration (s) | 0 | 0 | n/a | n/a | n/a
| remove_test_chain duration (s) | 0 | 0 | n/a | n/a | n/a
| fork_test_chain duration (s) | 0 | 0 | n/a | n/a | n/a
| checkout duration (s) | 2238.438 ms | 0% | 0.004 ms | 3.976 ms | 0.015 ms
| clear_test_chain duration (s) | 0 | 0 | n/a | n/a | n/a
| restore_context duration (s) | 0 | 0 | n/a | n/a | n/a
| init duration (s) | 39.847 ms | 0% | 39.847 ms | 39.847 ms | 39.847 ms
| close duration (s) | 0 | 0 | n/a | n/a | n/a
| dump_context duration (s) | 0 | 0 | n/a | n/a | n/a
| unseen duration (s) | 29min32s | 14% | 1.675 ms | 0.393 s | 12.224 ms
| | | | | |
| Major heap bytes after commit | n/a | n/a | 10.654 M | 334.193 M | 239.854 M
| | | | | |
| CPU Usage | n/a | n/a | 10% | 100% | 97%
-- evolution through blocks --
| Block played count *C | 0 (before) | 7975 | 15950 | 23200 | 31175 | 38425 | 46400 | 53650 | 61625 | 68875 | 76850 | 84100 | 92075 | 99325.0 | 107300 | 114550 | 122525 | 129775 | 137750 | 145000 (end)
| Blocks progress *C | 0% | 6% | 11% | 16% | 22% | 26% | 32% | 37% | 42% | 48% | 53% | 58% | 64% | 68% | 74% | 79% | 84% | 90% | 95% | 100%
| Block level | 0 | 1_924_894 | 1_932_859 | 1_940_097 | 1_948_062 | 1_955_303 | 1_963_269 | 1_970_511 | 1_978_477 | 1_985_719 | 1_993_683 | 2_000_925 | 2_008_893 | 2_016_135 | 2_024_100 | 2_031_341 | 2_039_303 | 2_046_545 | 2_054_507 | 2_061_749
| | | | | | | | | | | | | | | | | | | | |
| Wall time elapsed *C | 0us | 9min30s | 20min22s | 29min3s | 39min47s | 49min27s | 1h | 1h11min | 1h21min | 1h32min | 1h44min | 1h54min | 2h7min | 2h19min | 2h32min | 2h44min | 2h57min | 3h11min | 3h25min | 3h36min
| CPU time elapsed *C | 0us | 9min16s | 19min54s | 28min24s | 38min54s | 48min23s | 59min17s | 1h9min | 1h20min | 1h31min | 1h42min | 1h52min | 2h5min | 2h16min | 2h28min | 2h40min | 2h52min | 3h5min | 3h18min | 3h28min
| CPU Usage *LA | n/a | 98% | 98% | 98% | 98% | 98% | 98% | 98% | 99% | 98% | 98% | 98% | 98% | 97% | 96% | 95% | 96% | 95% | 93% | 94%
| | | | | | | | | | | | | | | | | | | | |
| TZ-operations count *C | 0.000 M | 1.383 M | 2.860 M | 4.000 M | 5.380 M | 6.614 M | 7.993 M | 9.334 M | 10.630 M | 12.021 M | 13.452 M | 14.704 M | 16.307 M | 17.615 M | 19.059 M | 20.471 M | 21.806 M | 23.171 M | 24.668 M | 25.871 M
| TZ-transaction count *C | 0.000 M | 0.850 M | 1.771 M | 2.408 M | 3.235 M | 3.967 M | 4.796 M | 5.634 M | 6.377 M | 7.268 M | 8.142 M | 8.887 M | 9.928 M | 10.734 M | 11.629 M | 12.537 M | 13.319 M | 14.178 M | 15.128 M | 15.823 M
| TZ-contrat count *C | 0.000 M | 0.589 M | 1.222 M | 1.641 M | 2.206 M | 2.681 M | 3.237 M | 3.806 M | 4.288 M | 4.889 M | 5.500 M | 5.998 M | 6.718 M | 7.271 M | 7.932 M | 8.608 M | 9.148 M | 9.777 M | 10.475 M | 10.943 M
| Context op count *C | 0.000 M | 57.125 M | 117.521 M | 164.181 M | 220.850 M | 271.009 M | 327.514 M | 382.506 M | 435.326 M | 491.882 M | 550.312 M | 601.689 M | 668.831 M | 723.546 M | 784.138 M | 846.134 M | 904.835 M | 977.518 M | 1050.004 M | 1102.342 M
| TZ-gas used *C | 0.000 G | 2.745 G | 5.657 G | 7.693 G | 10.522 G | 12.878 G | 15.496 G | 18.149 G | 20.537 G | 23.263 G | 26.128 G | 28.782 G | 32.488 G | 35.235 G | 38.410 G | 42.252 G | 45.558 G | 52.085 G | 57.556 G | 60.431 G
| TZ-storage size *C | 0.000 M | 23.849 M | 47.397 M | 64.661 M | 89.378 M | 113.772 M | 144.962 M | 173.379 M | 193.434 M | 224.108 M | 246.086 M | 262.471 M | 292.432 M | 314.695 M | 341.835 M | 367.304 M | 388.605 M | 411.582 M | 433.943 M | 450.294 M
| TZ-cycle snapshot *C | 0 | 1 | 2 | 3 | 4 | 5 | 5 | 7 | 7 | 8 | 10 | 10 | 11 | 13 | 13 | 14 | 15 | 15 | 17 | 17
| TZ-time *C | 0.000 T | 13068.970 T | 26139.952 T | 38024.399 T | 51099.179 T | 62987.059 T | 76065.612 T | 87956.935 T | 101039.287 T | 112934.054 T | 126020.193 T | 137918.408 T | 151008.347 T | 162910.014 T | 176003.762 T | 187908.884 T | 201006.395 T | 212914.927 T | 226016.195 T | 237928.159 T
| TZ-solve time *C | 0 | 281_026 | 533_346 | 761_102 | 1_009_592 | 1_235_322 | 1_483_582 | 1_713_586 | 1_961_026 | 2_189_666 | 2_439_266 | 2_667_746 | 2_918_246 | 3_146_866 | 3_399_136 | 3_623_196 | 3_870_986 | 4_094_196 | 4_344_946 | 4_568_796
| TZ-operations per block *C | n/a | 167.881 | 167.175 | 155.112 | 173.063 | 164.883 | 167.931 | 178.762 | 167.321 | 187.631 | 178.871 | 184.552 | 217.124 | 194.598 | 184.153 | 197.501 | 156.315 | 182.855 | 174.774 | 163.906
| TZ-transaction per block *C | n/a | 99.465 | 98.362 | 86.147 | 103.951 | 95.581 | 98.610 | 108.888 | 97.532 | 118.241 | 108.428 | 114.193 | 146.660 | 125.772 | 115.668 | 128.532 | 87.240 | 113.903 | 106.076 | 93.569
| TZ-contrat per block *C | n/a | 71.038 | 72.902 | 62.357 | 75.164 | 66.207 | 68.786 | 75.983 | 66.170 | 80.724 | 71.203 | 71.708 | 95.370 | 74.476 | 80.675 | 96.749 | 65.947 | 91.415 | 81.692 | 67.416
| Context op per block *C | n/a | 6_907 | 6_847 | 6_351 | 7_089 | 6_697 | 6_826 | 7_315 | 6_811 | 7_631 | 7_300 | 7_581 | 9_192 | 8_164 | 7_721 | 8_689 | 6_916 | 10_802 | 8_059 | 7_187
| | | | | | | | | | | | | | | | | | | | |
| tree.empty count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.of_raw count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.of_value count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.mem count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.mem_tree count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.find count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.is_empty count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.kind count per block *LA | n/a | 0 | 0.015 | 0.022 | 0.024 | 0.034 | 0.038 | 0.052 | 0.057 | 0.082 | 0.090 | 0.146 | 0.142 | 0.204 | 0.223 | 0.014 | 0.015 | 0.022 | 0.024 | 0.035
| tree.hash count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.equal count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.to_value count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0.006 | 0.000 | 0.000
| tree.clear count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.find_tree count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.add count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.add_tree count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.remove count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.fold count per block *LA | n/a | 0 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.001 | 0.000 | 0.001 | 0.001 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000
| find_tree count per block *LA | n/a | 0.340 | 0.333 | 0.329 | 0.322 | 0.286 | 0.337 | 0.334 | 0.276 | 0.302 | 0.323 | 0.388 | 0.371 | 0.337 | 0.387 | 0.400 | 0.386 | 0.340 | 0.375 | 0.355
| fold count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| add_tree count per block *LA | n/a | 0.340 | 0.333 | 0.329 | 0.322 | 0.286 | 0.337 | 0.334 | 0.276 | 0.302 | 0.323 | 0.388 | 0.371 | 0.337 | 0.387 | 0.400 | 0.386 | 0.340 | 0.375 | 0.355
| mem count per block *LA | n/a | 1338.835 | 1317.406 | 1183.857 | 1384.142 | 1280.383 | 1312.481 | 1457.313 | 1323.336 | 1546.149 | 1465.205 | 1537.549 | 1983.741 | 1721.840 | 1567.938 | 1796.247 | 1308.485 | 2257.244 | 1607.110 | 1385.412
| mem_tree count per block *LA | n/a | 324.585 | 324.803 | 325.229 | 325.265 | 325.595 | 325.560 | 325.805 | 325.793 | 325.223 | 326.034 | 326.229 | 326.199 | 324.776 | 324.284 | 324.592 | 325.128 | 324.671 | 324.884 | 326.571
| find count per block *LA | n/a | 3851.009 | 3820.520 | 3583.103 | 3946.781 | 3744.199 | 3806.922 | 4048.857 | 3810.692 | 4194.367 | 4055.675 | 4202.823 | 5049.278 | 4502.542 | 4292.936 | 4857.233 | 3985.893 | 6622.246 | 4672.380 | 4138.296
| get_protocol count per block *LA | n/a | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.999 | 3.998 | 3.999
| hash count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| find_predecessor_block_metadata_hash count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| find_predecessor_ops_metadata_hash count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| get_test_chain count per block *LA | n/a | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000
| exists count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| retrieve_commit_info count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| add count per block *LA | n/a | 1368.063 | 1357.662 | 1235.460 | 1407.092 | 1324.004 | 1357.121 | 1455.504 | 1327.561 | 1539.034 | 1426.199 | 1485.147 | 1801.882 | 1586.824 | 1505.938 | 1680.407 | 1267.844 | 1569.954 | 1427.078 | 1310.700
| remove count per block *LA | n/a | 15.181 | 16.954 | 13.682 | 15.766 | 13.125 | 13.848 | 17.343 | 14.311 | 16.594 | 17.032 | 18.694 | 21.036 | 17.510 | 19.518 | 21.065 | 19.005 | 18.351 | 17.852 | 16.006
| add_protocol count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| add_predecessor_block_metadata_hash count per block *LA | n/a | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000
| add_predecessor_ops_metadata_hash count per block *LA | n/a | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000
| add_test_chain count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| remove_test_chain count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| fork_test_chain count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| checkout count per block *LA | n/a | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.999 | 0.998 | 0.999
| clear_test_chain count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| init count per block *LA | n/a | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000
| restore_context count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| commit count per block *LA | n/a | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000 | 1.000
| close count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| dump_context count per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| | | | | | | | | | | | | | | | | | | | |
| block duration *LA | n/a | 73.110 ms | 76.078 ms | 72.948 ms | 83.326 ms | 78.561 ms | 81.569 ms | 86.699 ms | 80.365 ms | 91.427 ms | 85.460 ms | 87.005 ms | 106.554 ms | 98.792 ms | 101.140 ms | 106.274 ms | 92.162 ms | 112.187 ms | 100.982 ms | 92.597 ms
| buildup duration *LA | n/a | 58.253 ms | 60.910 ms | 58.467 ms | 66.453 ms | 62.816 ms | 65.121 ms | 69.230 ms | 64.185 ms | 72.998 ms | 68.500 ms | 70.066 ms | 86.014 ms | 79.719 ms | 81.444 ms | 85.717 ms | 74.283 ms | 92.334 ms | 82.896 ms | 75.419 ms
| commit duration *LA | n/a | 14.856 ms | 15.168 ms | 14.481 ms | 16.872 ms | 15.745 ms | 16.448 ms | 17.469 ms | 16.180 ms | 18.429 ms | 16.960 ms | 16.939 ms | 20.539 ms | 19.073 ms | 19.696 ms | 20.558 ms | 17.879 ms | 19.853 ms | 18.086 ms | 17.178 ms
| | | | | | | | | | | | | | | | | | | | |
| tree.empty duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.of_raw duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.of_value duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.mem duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.mem_tree duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.find duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.is_empty duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.kind duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.hash duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.equal duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.to_value duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.clear duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.find_tree duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.add duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.add_tree duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.remove duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| tree.fold duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| find_tree duration *LA | n/a | 2.037 µs | 2.285 µs | 1.831 µs | 1.853 µs | 1.861 µs | 1.893 µs | 1.527 µs | 1.650 µs | 1.446 µs | 1.552 µs | 1.463 µs | 2.582 µs | 1.980 µs | 1.850 µs | 2.418 µs | 1.967 µs | 1.315 µs | 3.936 µs | 2.088 µs
| fold duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| add_tree duration *LA | n/a | 55.113 µs | 61.728 µs | 81.172 µs | 70.903 µs | 96.375 µs | 90.051 µs | 74.635 µs | 145.759 µs | 82.601 µs | 79.846 µs | 78.752 µs | 275.978 µs | 94.036 µs | 82.624 µs | 88.783 µs | 153.644 µs | 128.703 µs | 91.346 µs | 137.143 µs
| mem duration *LA | n/a | 10.950 µs | 11.873 µs | 12.544 µs | 12.313 µs | 12.746 µs | 12.854 µs | 12.862 µs | 13.067 µs | 12.842 µs | 13.016 µs | 12.784 µs | 12.574 µs | 14.090 µs | 15.454 µs | 14.274 µs | 15.934 µs | 11.338 µs | 17.624 µs | 16.796 µs
| mem_tree duration *LA | n/a | 1.943 µs | 1.993 µs | 2.058 µs | 2.118 µs | 2.093 µs | 2.088 µs | 2.043 µs | 2.074 µs | 2.127 µs | 2.155 µs | 2.108 µs | 2.149 µs | 2.206 µs | 2.184 µs | 2.151 µs | 2.134 µs | 2.132 µs | 2.093 µs | 2.118 µs
| find duration *LA | n/a | 7.960 µs | 8.418 µs | 8.796 µs | 8.916 µs | 8.900 µs | 9.148 µs | 8.960 µs | 8.966 µs | 9.170 µs | 9.056 µs | 9.002 µs | 8.875 µs | 9.556 µs | 9.655 µs | 8.898 µs | 9.605 µs | 7.149 µs | 9.336 µs | 9.385 µs
| get_protocol duration *LA | n/a | 5.696 µs | 4.917 µs | 4.969 µs | 5.970 µs | 5.261 µs | 5.288 µs | 5.406 µs | 5.635 µs | 5.813 µs | 6.708 µs | 5.155 µs | 7.071 µs | 6.982 µs | 7.460 µs | 6.350 µs | 5.715 µs | 6.328 µs | 5.856 µs | 6.095 µs
| hash duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| find_predecessor_block_metadata_hash duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| find_predecessor_ops_metadata_hash duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| get_test_chain duration *LA | n/a | 7.538 µs | 6.801 µs | 7.008 µs | 8.100 µs | 9.174 µs | 6.895 µs | 8.756 µs | 8.263 µs | 7.686 µs | 8.228 µs | 7.027 µs | 9.340 µs | 10.812 µs | 9.967 µs | 9.216 µs | 9.965 µs | 7.556 µs | 12.373 µs | 10.035 µs
| exists duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| retrieve_commit_info duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| add duration *LA | n/a | 3.156 µs | 3.208 µs | 3.395 µs | 3.416 µs | 3.389 µs | 3.398 µs | 3.313 µs | 3.385 µs | 3.366 µs | 3.440 µs | 3.333 µs | 3.362 µs | 3.527 µs | 3.544 µs | 3.429 µs | 3.652 µs | 3.370 µs | 3.450 µs | 3.485 µs
| remove duration *LA | n/a | 4.865 µs | 4.937 µs | 5.241 µs | 5.266 µs | 5.313 µs | 5.308 µs | 5.303 µs | 5.341 µs | 5.501 µs | 5.089 µs | 5.140 µs | 5.462 µs | 5.804 µs | 5.649 µs | 5.479 µs | 5.530 µs | 5.571 µs | 5.724 µs | 5.556 µs
| add_protocol duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| add_predecessor_block_metadata_hash duration *LA | n/a | 12.534 µs | 10.146 µs | 10.945 µs | 13.063 µs | 10.615 µs | 11.530 µs | 12.009 µs | 9.844 µs | 10.112 µs | 12.896 µs | 14.680 µs | 11.696 µs | 9.795 µs | 12.697 µs | 11.471 µs | 12.728 µs | 13.156 µs | 11.171 µs | 12.195 µs
| add_predecessor_ops_metadata_hash duration *LA | n/a | 6.929 µs | 6.626 µs | 8.129 µs | 6.253 µs | 7.646 µs | 8.836 µs | 5.826 µs | 5.536 µs | 7.542 µs | 6.872 µs | 7.455 µs | 7.364 µs | 8.678 µs | 6.504 µs | 7.451 µs | 6.255 µs | 7.650 µs | 4.238 µs | 9.802 µs
| add_test_chain duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| remove_test_chain duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| fork_test_chain duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| checkout duration *LA | n/a | 12.804 µs | 13.696 µs | 15.148 µs | 14.506 µs | 13.058 µs | 16.478 µs | 15.208 µs | 13.888 µs | 14.351 µs | 15.739 µs | 13.754 µs | 16.001 µs | 17.387 µs | 17.372 µs | 16.602 µs | 14.940 µs | 19.990 µs | 15.454 µs | 16.665 µs
| clear_test_chain duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| init duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| restore_context duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| close duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| dump_context duration *LA | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a | n/a
| unseen duration *LA | n/a | 10.354 ms | 10.312 ms | 9.729 ms | 11.411 ms | 10.444 ms | 10.544 ms | 11.235 ms | 10.401 ms | 12.226 ms | 11.582 ms | 11.733 ms | 15.287 ms | 13.495 ms | 13.169 ms | 14.745 ms | 11.634 ms | 19.031 ms | 13.446 ms | 11.608 ms
| | | | | | | | | | | | | | | | | | | | |
| Disk bytes read *C | 0.000 G | 8.202 G | 16.931 G | 23.574 G | 31.792 G | 39.164 G | 47.661 G | 56.133 G | 63.988 G | 72.678 G | 81.286 G | 88.819 G | 98.608 G | 106.956 G | 116.490 G | 125.468 G | 134.455 G | 143.477 G | 153.123 G | 160.803 G
| Disk bytes written *C | 0.000 G | 2.998 G | 6.176 G | 8.640 G | 11.592 G | 14.229 G | 17.287 G | 20.289 G | 23.115 G | 26.209 G | 29.322 G | 32.042 G | 35.536 G | 38.543 G | 41.995 G | 45.254 G | 48.459 G | 51.677 G | 55.101 G | 57.854 G
| Disk bytes both *C | 0.000 G | 11.200 G | 23.107 G | 32.215 G | 43.384 G | 53.393 G | 64.948 G | 76.422 G | 87.103 G | 98.887 G | 110.607 G | 120.861 G | 134.144 G | 145.500 G | 158.485 G | 170.723 G | 182.914 G | 195.154 G | 208.224 G | 218.657 G
| Disk bytes read per block *LA | n/a | 1_015_242 | 1_022_813 | 927_077 | 1_064_265 | 995_256 | 1_045_868 | 1_141_639 | 1_025_214 | 1_168_208 | 1_043_129 | 1_097_170 | 1_338_793 | 1_195_076 | 1_205_744 | 1_246_602 | 1_079_649 | 1_237_559 | 1_122_259 | 1_072_883
| Disk bytes written per block *LA | n/a | 375_518 | 370_943 | 344_135 | 381_507 | 361_513 | 377_584 | 402_585 | 368_454 | 423_092 | 379_205 | 389_071 | 470_540 | 427_085 | 435_541 | 452_134 | 383_284 | 443_229 | 405_311 | 386_380
| Disk bytes both per block *LA | n/a | 1_390_760 | 1_393_756 | 1_271_212 | 1_445_772 | 1_356_769 | 1_423_451 | 1_544_223 | 1_393_668 | 1_591_300 | 1_422_334 | 1_486_241 | 1_809_333 | 1_622_161 | 1_641_285 | 1_698_737 | 1_462_933 | 1_680_788 | 1_527_570 | 1_459_263
| Disk bytes read per sec *LA *N | n/a | 13.887 M | 13.444 M | 12.709 M | 12.772 M | 12.669 M | 12.822 M | 13.168 M | 12.757 M | 12.778 M | 12.206 M | 12.610 M | 12.564 M | 12.097 M | 11.922 M | 11.730 M | 11.715 M | 11.031 M | 11.113 M | 11.587 M
| Disk bytes written per sec *LA *N | n/a | 5.136 M | 4.876 M | 4.718 M | 4.578 M | 4.602 M | 4.629 M | 4.643 M | 4.585 M | 4.628 M | 4.437 M | 4.472 M | 4.416 M | 4.323 M | 4.306 M | 4.254 M | 4.159 M | 3.951 M | 4.014 M | 4.173 M
| Disk bytes both per sec *LA *N | n/a | 19.023 M | 18.320 M | 17.426 M | 17.351 M | 17.270 M | 17.451 M | 17.811 M | 17.342 M | 17.405 M | 16.643 M | 17.082 M | 16.980 M | 16.420 M | 16.228 M | 15.984 M | 15.873 M | 14.982 M | 15.127 M | 15.759 M
| | | | | | | | | | | | | | | | | | | | |
| Disk read count *C | 0.000 M | 145.962 M | 301.230 M | 420.324 M | 567.184 M | 698.433 M | 849.548 M | 999.797 M | 1140.213 M | 1293.816 M | 1446.271 M | 1579.966 M | 1752.080 M | 1898.932 M | 2066.136 M | 2223.137 M | 2382.308 M | 2541.293 M | 2710.437 M | 2845.668 M
| Disk write count *C | 0 | 47_940 | 95_935 | 139_511 | 187_452 | 231_024 | 278_971 | 322_599 | 370_511 | 414_175 | 462_103 | 505_653 | 553_713 | 597_390 | 645_409 | 689_042 | 736_995 | 780_664 | 828_659 | 872_231
| Disk both count *C | 0.000 M | 146.010 M | 301.326 M | 420.464 M | 567.371 M | 698.664 M | 849.827 M | 1000.120 M | 1140.583 M | 1294.231 M | 1446.733 M | 1580.471 M | 1752.634 M | 1899.529 M | 2066.782 M | 2223.826 M | 2383.045 M | 2542.074 M | 2711.265 M | 2846.541 M
| Disk read count per block *LA | n/a | 18074.601 | 18249.680 | 16602.208 | 18963.486 | 17690.470 | 18568.787 | 20255.728 | 18315.612 | 20603.174 | 18524.242 | 19462.160 | 23545.130 | 21097.397 | 21142.358 | 21835.369 | 19152.404 | 21808.793 | 19593.349 | 18853.776
| Disk write count per block *LA | n/a | 6.009 | 6.012 | 6.007 | 6.013 | 6.009 | 6.010 | 6.012 | 6.006 | 6.021 | 6.011 | 6.008 | 6.029 | 6.032 | 6.024 | 6.020 | 6.008 | 6.020 | 6.016 | 6.008
| Disk both count per block *LA | n/a | 18080.609 | 18255.692 | 16608.215 | 18969.500 | 17696.478 | 18574.796 | 20261.741 | 18321.619 | 20609.196 | 18530.252 | 19468.168 | 23551.159 | 21103.430 | 21148.382 | 21841.389 | 19158.413 | 21814.812 | 19599.365 | 18859.785
| Disk read count per sec *LA *N | n/a | 247_226 | 239_882 | 227_591 | 227_583 | 225_182 | 227_645 | 233_632 | 227_904 | 225_351 | 216_760 | 223_690 | 220_969 | 213_553 | 209_041 | 205_462 | 207_811 | 194_397 | 194_028 | 203_612
| Disk write count per sec *LA *N | n/a | 82 | 79 | 82 | 72 | 76 | 74 | 69 | 75 | 66 | 70 | 69 | 57 | 61 | 60 | 57 | 65 | 54 | 60 | 65
| Disk both count per sec *LA *N | n/a | 247_308 | 239_961 | 227_673 | 227_655 | 225_259 | 227_718 | 233_702 | 227_979 | 225_417 | 216_830 | 223_759 | 221_026 | 213_614 | 209_101 | 205_519 | 207_876 | 194_451 | 194_087 | 203_677
| | | | | | | | | | | | | | | | | | | | |
| pack.finds_total per block *LA | n/a | 5016.712 | 4999.545 | 4776.540 | 5111.631 | 4942.552 | 4999.804 | 5239.618 | 5009.764 | 5266.258 | 5270.857 | 5396.612 | 6073.285 | 5640.651 | 5537.875 | 5991.002 | 5366.184 | 7422.342 | 5933.138 | 5532.851
| pack.finds_from_staging per block *LA | n/a | 3.146e-03 | 3.377e-04 | 1.450e-03 | 1.513e-03 | 7.585e-04 | 1.250e-03 | 1.527e-03 | 1.898e-03 | 2.746e-03 | 1.769e-03 | 1.428e-03 | 1.626e-03 | 1.795e-03 | 3.842e-03 | 8.640e-03 | 9.073e-04 | 4.862e-04 | 3.866e-03 | 4.923e-03
| pack.finds_from_lru per block *LA | n/a | 3688.737 | 3659.102 | 3542.852 | 3724.729 | 3607.058 | 3622.508 | 3754.208 | 3687.141 | 3754.978 | 3876.741 | 3906.793 | 4292.890 | 4052.807 | 3955.402 | 4336.743 | 3914.263 | 5738.979 | 4381.804 | 4051.458
| pack.finds_from_pack_direct per block *LA | n/a | 1327.972 | 1340.443 | 1233.687 | 1386.901 | 1335.493 | 1377.295 | 1485.409 | 1322.622 | 1511.277 | 1394.114 | 1489.818 | 1780.394 | 1587.843 | 1582.469 | 1654.251 | 1451.921 | 1683.363 | 1551.330 | 1481.388
| pack.finds_from_pack_indexed per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| pack.cache_misses per block *LA | n/a | 1327.972 | 1340.443 | 1233.687 | 1386.901 | 1335.493 | 1377.295 | 1485.409 | 1322.622 | 1511.277 | 1394.114 | 1489.818 | 1780.394 | 1587.843 | 1582.469 | 1654.251 | 1451.921 | 1683.363 | 1551.330 | 1481.388
| pack.appended_hashes per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| pack.appended_offsets per block *LA | n/a | 18_460 | 18_502 | 17_207 | 19_131 | 18_335 | 19_007 | 20_340 | 18_592 | 21_053 | 19_154 | 19_589 | 23_536 | 21_320 | 21_524 | 22_462 | 19_615 | 22_163 | 20_580 | 19_933
| pack.inode_add per block *LA | n/a | 820.164 | 815.440 | 769.064 | 835.624 | 809.010 | 821.611 | 862.837 | 805.769 | 877.406 | 833.372 | 851.472 | 962.547 | 885.178 | 885.409 | 921.815 | 817.564 | 905.631 | 860.509 | 833.601
| pack.inode_remove per block *LA | n/a | 6.938_859 | 8.215_030 | 6.545_047 | 7.170_823 | 6.085_010 | 6.548_105 | 8.279_641 | 6.786_820 | 7.904_804 | 7.893_043 | 8.709_005 | 9.466_183 | 8.363_969 | 9.195_056 | 9.874_381 | 8.740_883 | 8.666_078 | 8.084_356 | 7.576_965
| pack.inode_of_seq per block *LA | n/a | 32.711 | 32.049 | 30.465 | 41.542 | 38.827 | 43.460 | 42.668 | 33.554 | 47.560 | 30.799 | 27.859 | 47.406 | 35.928 | 39.157 | 44.870 | 30.443 | 41.052 | 30.436 | 28.189
| pack.inode_of_raw per block *LA | n/a | 1622.605 | 1619.460 | 1569.172 | 1646.981 | 1605.700 | 1614.859 | 1678.983 | 1628.136 | 1669.254 | 1696.015 | 1714.906 | 1889.176 | 1763.297 | 1751.169 | 1916.999 | 1754.211 | 2457.417 | 1928.167 | 1804.699
| pack.inode_rec_add per block *LA | n/a | 1606.061 | 1589.604 | 1490.894 | 1645.649 | 1589.181 | 1627.731 | 1720.486 | 1589.155 | 1772.684 | 1640.912 | 1676.767 | 1955.300 | 1780.577 | 1755.852 | 1812.278 | 1568.922 | 1787.821 | 1650.909 | 1602.341
| pack.inode_rec_remove per block *LA | n/a | 11.498 | 15.430 | 11.890 | 13.563 | 10.059 | 12.173 | 17.192 | 13.165 | 16.603 | 14.926 | 15.265 | 19.150 | 17.343 | 18.572 | 17.539 | 16.154 | 17.330 | 14.949 | 13.661
| pack.inode_to_binv per block *LA | n/a | 1865.649 | 1863.039 | 1733.586 | 1932.984 | 1856.283 | 1913.722 | 2034.647 | 1856.058 | 2097.450 | 1912.705 | 1956.978 | 2332.281 | 2108.672 | 2107.706 | 2199.631 | 1902.880 | 2181.582 | 1999.874 | 1929.035
| pack.inode_decode_bin per block *LA | n/a | 1108.715 | 1113.704 | 1031.743 | 1146.255 | 1102.920 | 1137.441 | 1220.867 | 1098.355 | 1234.395 | 1151.184 | 1218.750 | 1417.371 | 1279.162 | 1271.995 | 1324.337 | 1171.116 | 1324.658 | 1239.815 | 1188.005
| pack.inode_encode_bin per block *LA | n/a | 1172.076 | 1172.484 | 1090.957 | 1214.184 | 1164.994 | 1198.503 | 1274.066 | 1163.820 | 1307.023 | 1202.525 | 1234.059 | 1462.153 | 1325.985 | 1331.029 | 1405.057 | 1225.292 | 1399.460 | 1288.212 | 1242.391
| | | | | | | | | | | | | | | | | | | | |
| tree.contents_hash per block *LA | n/a | 634.264 | 628.553 | 599.674 | 656.306 | 636.115 | 649.732 | 676.477 | 632.488 | 693.645 | 653.209 | 662.886 | 755.012 | 693.937 | 683.602 | 710.859 | 624.896 | 700.245 | 655.052 | 637.801
| tree.contents_find per block *LA | n/a | 1692.310 | 1676.705 | 1569.908 | 1722.959 | 1635.632 | 1654.781 | 1760.768 | 1672.626 | 1783.747 | 1801.945 | 1870.306 | 2203.402 | 2016.011 | 1930.634 | 2143.028 | 1830.342 | 2971.119 | 2143.298 | 1910.895
| tree.contents_add per block *LA | n/a | 467.745 | 464.287 | 437.651 | 490.516 | 470.714 | 485.236 | 506.040 | 462.298 | 522.302 | 474.191 | 476.985 | 565.468 | 504.991 | 510.620 | 538.636 | 460.760 | 526.266 | 482.715 | 464.839
| tree.contents_mem per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.node_hash per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.node_mem per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.node_index per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.node_add per block *LA | n/a | 420.180 | 417.382 | 394.598 | 430.720 | 418.093 | 425.534 | 444.617 | 412.819 | 452.776 | 423.590 | 432.849 | 494.614 | 454.397 | 455.814 | 475.897 | 420.142 | 463.953 | 440.961 | 427.384
| tree.node_find per block *LA | n/a | 1622.605 | 1619.460 | 1569.172 | 1646.981 | 1605.700 | 1614.859 | 1678.983 | 1628.136 | 1669.254 | 1696.015 | 1714.906 | 1889.176 | 1763.297 | 1751.169 | 1916.999 | 1754.211 | 2457.417 | 1928.167 | 1804.699
| tree.node_val_v per block *LA | n/a | 32.711 | 32.049 | 30.465 | 41.542 | 38.827 | 43.460 | 42.668 | 33.554 | 47.560 | 30.799 | 27.859 | 47.406 | 35.928 | 39.157 | 44.870 | 30.443 | 41.052 | 30.436 | 28.189
| tree.node_val_find per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| tree.node_val_list per block *LA | n/a | 4.131_211 | 4.555_248 | 4.130_645 | 4.553_410 | 3.634_512 | 4.206_693 | 5.463_769 | 4.576_478 | 5.430_584 | 5.183_219 | 5.095_600 | 5.881_021 | 5.522_803 | 5.993_447 | 5.824_525 | 5.420_855 | 5.920_304 | 4.958_095 | 4.591_851
| | | | | | | | | | | | | | | | | | | | |
| index.nb_merge *C | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| index.cumu_data_bytes *C | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| index.cumu_data_bytes per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| | | | | | | | | | | | | | | | | | | | |
| gc.minor_words allocated *C | 0.004 G | 126.441 G | 265.446 G | 374.487 G | 506.045 G | 624.504 G | 759.109 G | 890.336 G | 1015.973 G | 1150.472 G | 1288.988 G | 1410.441 G | 1565.160 G | 1695.261 G | 1841.235 G | 1982.730 G | 2121.985 G | 2272.353 G | 2430.796 G | 2554.194 G
| gc.minor_words allocated per block *LA | n/a | 15.947 M | 16.148 M | 15.061 M | 16.772 M | 16.003 M | 16.478 M | 17.621 M | 16.262 M | 18.149 M | 17.005 M | 17.644 M | 20.976 M | 18.951 M | 18.541 M | 19.701 M | 16.718 M | 21.367 M | 18.197 M | 17.068 M
| gc.promoted_words *C | 0.001 G | 9.713 G | 19.983 G | 28.019 G | 37.700 G | 46.423 G | 56.347 G | 66.016 G | 75.219 G | 85.115 G | 95.270 G | 104.144 G | 115.513 G | 125.099 G | 135.925 G | 146.384 G | 156.740 G | 167.973 G | 179.784 G | 188.921 G
| gc.major_words allocated *C | 0.001 G | 10.865 G | 22.356 G | 31.325 G | 42.139 G | 51.863 G | 62.927 G | 73.707 G | 83.964 G | 94.998 G | 106.344 G | 116.275 G | 128.993 G | 139.700 G | 151.793 G | 163.499 G | 175.057 G | 187.752 G | 201.007 G | 211.197 G
| gc.major_words allocated per block *LA | n/a | 1_339_157 | 1_336_378 | 1_242_375 | 1_381_067 | 1_316_218 | 1_357_119 | 1_450_131 | 1_329_757 | 1_495_910 | 1_392_314 | 1_438_554 | 1_722_407 | 1_543_546 | 1_527_050 | 1_632_447 | 1_386_872 | 1_830_183 | 1_521_671 | 1_418_562
| gc.minor_collections *C | 15 | 483_711 | 1_015_292 | 1_432_229 | 1_935_218 | 2_388_070 | 2_902_544 | 3_404_054 | 3_884_179 | 4_398_167 | 4_927_502 | 5_391_613 | 5_983_049 | 6_480_350 | 7_038_257 | 7_579_007 | 8_111_200 | 8_685_821 | 9_291_248 | 9_762_739
| gc.minor_collections per block *LA | n/a | 60.999 | 61.753 | 57.587 | 64.123 | 61.174 | 62.978 | 67.340 | 62.146 | 69.357 | 64.986 | 67.423 | 80.179 | 72.438 | 70.865 | 75.289 | 63.888 | 81.655 | 69.534 | 65.216
| gc.major_collections *C | 2 | 2_659 | 5_188 | 7_068 | 9_225 | 11_070 | 12_967 | 14_710 | 16_340 | 18_063 | 19_835 | 21_351 | 23_655 | 25_512 | 27_474 | 29_313 | 31_115 | 32_883 | 34_717 | 36_130
| gc.major_collections per block *LA | n/a | 0.321_602 | 0.294_706 | 0.260_318 | 0.274_586 | 0.249_016 | 0.228_108 | 0.233_690 | 0.210_548 | 0.233_112 | 0.217_244 | 0.215_607 | 0.304_835 | 0.263_510 | 0.247_190 | 0.256_298 | 0.217_207 | 0.254_917 | 0.211_408 | 0.196_766
| gc.compactions *C | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 1 | 1 | 1 | 1 | 1 | 1 | 1
| | | | | | | | | | | | | | | | | | | | |
| gc.major heap bytes top *C | 10.654 M | 144.474 M | 144.474 M | 166.146 M | 166.146 M | 191.070 M | 290.599 M | 290.599 M | 290.599 M | 290.599 M | 290.599 M | 334.193 M | 334.193 M | 334.193 M | 334.193 M | 334.193 M | 334.193 M | 334.193 M | 334.193 M | 334.193 M
| gc.major heap bytes *LA | n/a | 134.854 M | 144.039 M | 164.504 M | 166.068 M | 188.139 M | 277.786 M | 289.798 M | 290.561 M | 290.597 M | 290.599 M | 314.485 M | 192.364 M | 197.676 M | 216.730 M | 217.619 M | 248.600 M | 324.831 M | 330.772 M | 331.049 M
| | | | | | | | | | | | | | | | | | | | |
| rusage.utime *C | 1.152s | 8min29s | 18min10s | 25min55s | 35min29s | 44min8s | 54min3s | 1h3min | 1h12min | 1h22min | 1h33min | 1h42min | 1h54min | 2h4min | 2h15min | 2h26min | 2h37min | 2h48min | 3h | 3h9min
| rusage.utime per block *LA | n/a | 65.175 ms | 67.913 ms | 65.245 ms | 74.218 ms | 70.249 ms | 72.888 ms | 77.520 ms | 72.054 ms | 81.385 ms | 76.508 ms | 77.914 ms | 94.643 ms | 86.663 ms | 86.672 ms | 90.253 ms | 79.302 ms | 95.521 ms | 83.387 ms | 77.831 ms
| rusage.stime *C | 274ms | 49.187s | 1min45s | 2min30s | 3min26s | 4min16s | 5min14s | 6min13s | 7min6s | 8min8s | 9min8s | 10min | 11min10s | 12min12s | 13min21s | 14min29s | 15min36s | 16min45s | 17min58s | 18min55s
| rusage.stime per block *LA | n/a | 6.303 ms | 6.609 ms | 6.247 ms | 7.404 ms | 6.805 ms | 7.228 ms | 7.679 ms | 7.011 ms | 8.316 ms | 7.411 ms | 7.548 ms | 9.616 ms | 8.710 ms | 8.946 ms | 9.306 ms | 8.014 ms | 9.520 ms | 8.454 ms | 7.899 ms
| rusage.maxrss *C | 152.244 M | 203.084 M | 241.844 M | 266.932 M | 297.136 M | 319.516 M | 455.684 M | 472.052 M | 485.344 M | 506.752 M | 519.740 M | 539.464 M | 543.440 M | 543.440 M | 543.440 M | 543.440 M | 543.440 M | 607.584 M | 617.256 M | 617.256 M
| rusage.minflt *C | 44_192 | 279_598 | 490_481 | 645_302 | 877_940 | 1_048_954 | 1_303_035 | 1_516_588 | 1_729_952 | 1_993_684 | 2_212_965 | 2_403_915 | 2_615_462 | 2_805_722 | 3_003_948 | 3_161_211 | 3_322_276 | 3_527_820 | 3_771_035 | 3_906_764
| rusage.minflt per block *LA | n/a | 23.164 | 23.470 | 17.564 | 30.690 | 23.549 | 30.802 | 25.071 | 21.797 | 37.331 | 32.112 | 28.813 | 22.098 | 29.476 | 31.729 | 21.702 | 13.283 | 19.364 | 28.556 | 17.321
| rusage.majflt *C | 495 | 496 | 497 | 497 | 497 | 497 | 497 | 499 | 499 | 499 | 499 | 501 | 1_226 | 8_354 | 18_188 | 26_576 | 35_267 | 38_182 | 38_190 | 38_193
| rusage.majflt per block *LA | n/a | 0.000_019 | 0.000_021 | 0.000_001 | 0.000_000 | 0.000_000 | 0.000_000 | 0.000_225 | 0.000_011 | 0.000_001 | 0.000_000 | 0.000_345 | 0.090_329 | 1.033_378 | 1.607_644 | 1.157_790 | 0.713_083 | 0.119_666 | 0.006_252 | 0.000_521
| rusage.inblock *C | 0.145 M | 9.495 M | 19.430 M | 26.938 M | 36.117 M | 44.158 M | 53.242 M | 62.120 M | 70.538 M | 79.666 M | 89.217 M | 97.660 M | 108.740 M | 118.720 M | 130.672 M | 142.933 M | 154.509 M | 169.251 M | 184.044 M | 194.362 M
| rusage.inblock per block *LA | n/a | 1140.062 | 1120.323 | 1029.824 | 1149.595 | 1072.993 | 1100.200 | 1182.282 | 1089.066 | 1230.549 | 1189.112 | 1236.619 | 1511.473 | 1482.818 | 1551.154 | 1725.635 | 1310.694 | 2150.180 | 1694.357 | 1439.041
| rusage.oublock *C | 0.003 M | 6.649 M | 13.690 M | 19.150 M | 25.699 M | 31.543 M | 38.298 M | 44.921 M | 51.172 M | 57.998 M | 64.885 M | 70.910 M | 78.662 M | 85.292 M | 92.871 M | 100.094 M | 107.166 M | 114.454 M | 122.142 M | 128.244 M
| rusage.oublock per block *LA | n/a | 829.015 | 819.260 | 760.119 | 843.210 | 798.805 | 831.968 | 887.479 | 813.941 | 931.883 | 841.649 | 864.736 | 1045.914 | 946.986 | 957.446 | 1003.111 | 844.373 | 1014.635 | 903.044 | 854.159
| rusage.nvcsw *C | 3_984 | 32_539 | 63_377 | 85_474 | 113_351 | 137_543 | 165_056 | 192_494 | 217_429 | 245_849 | 275_218 | 300_991 | 336_518 | 382_978 | 498_222 | 647_459 | 790_733 | 1_001_340 | 1_280_990 | 1_467_130
| rusage.nvcsw per block *LA | n/a | 3.455 | 3.378 | 3.026 | 3.490 | 3.195 | 3.298 | 3.621 | 3.257 | 3.807 | 3.651 | 3.838 | 4.930 | 7.179 | 15.187 | 21.077 | 14.575 | 25.714 | 36.125 | 26.910
| rusage.nivcsw *C | 1_401 | 3_133 | 5_511 | 7_072 | 8_512 | 9_683 | 11_136 | 12_657 | 14_049 | 15_895 | 17_511 | 19_952 | 22_986 | 25_624 | 29_044 | 31_279 | 34_386 | 38_728 | 44_065 | 46_624
| rusage.nivcsw per block *LA | n/a | 0.203_222 | 0.273_722 | 0.180_307 | 0.200_353 | 0.158_538 | 0.181_731 | 0.197_338 | 0.166_462 | 0.255_208 | 0.201_560 | 0.373_545 | 0.375_104 | 0.307_984 | 0.461_399 | 0.332_804 | 0.352_706 | 0.689_083 | 0.642_552 | 0.355_433
| | | | | | | | | | | | | | | | | | | | |
| index_data bytes *S | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| index_data bytes per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| store_pack bytes *S | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| store_pack bytes per block *LA | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| index_log bytes *S | n/a | 259_197 | 601_838 | 926_587 | 1_285_271 | 1_611_510 | 1_970_384 | 2_296_634 | 2_655_509 | 2_981_759 | 3_340_597 | 3_666_839 | 4_025_714 | 4_351_964 | 4_710_839 | 5_037_086 | 5_395_813 | 5_722_025 | 6_080_781 | 6_407_024
| index_log_async *S | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| store_dict bytes *S | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903 | 6_697_903
| | | | | | | | | | | | | | | | | | | | |
| /data/contracts/index *S | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| /data/big_maps/index *S | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| /data/rolls/index *S | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| /data/rolls/owner/current *S | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
| /data/commitments *S | n/a | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0
Types of curves:
*C: Cumulative. No smoothing.
*LA: Local Average. Smoothed using a weighted sum of the value in the
block and the exponentially decayed values of the previous blocks.
Every 1812.51 blocks, half of the past is forgotten.
*S: Size. E.g. directory entries, file bytes. No smoothing.
*N: Very noisy.
I ran a benchmark with latest main that gc'd every 8100 commits (roughly equivalent to a Tezos cycle) and noticed that transfer_latest_newies_duration increased significantly. After patching with #1986 the commit tail latency went back down to below 1 second. @zshipko let's reopen that PR and work to merge it for 3.4.
Here are the latest results from different runs (including one without gc for a baseline comparison):
| | no_gc | gc_20 | gc_8100 | gc_8100_loop
| -- | -- | -- | -- | --
| -- main metrics -- | | | |
| CPU time elapsed | 160m43s | 202m13s 126% | 192m58s 120% | 192m21s 120%
| Wall time elapsed | 231m05s | 210m34s 91% | 232m38s 101% | 231m55s 100%
| TZ-transactions per sec | 1640.910 | 1304.126 79% | 1366.596 83% | 1370.961 84%
| TZ-operations per sec | 2682.982 | 2132.321 79% | 2234.463 83% | 2241.601 84%
| Context.add per sec | 21869.992 | 17381.342 79% | 18213.942 83% | 18272.123 84%
| tail latency (1) | 0.507 s | 0.812 s 160% | 1.415 s 279% | 0.640 s 126%
| | | | |
| -- resource usage -- | | | |
| disk IO (total) | | | |
| IOPS (op/sec) | 295_128 | 234_616 79% | 245_818 83% | 246_585 84%
| throughput (bytes/sec) | 22.528 M | 18.025 M 80% | 19.016 M 84% | 18.820 M 84%
| total (bytes) | 217.225 G | 218.697 G 101% | 220.170 G 101% | 217.206 G 100%
| disk IO (read) | | | |
| IOPS (op/sec) | 295_037 | 234_544 79% | 245_743 83% | 246_510 84%
| throughput (bytes/sec) | 16.603 M | 13.255 M 80% | 13.953 M 84% | 13.870 M 84%
| total (bytes) | 160.094 G | 160.823 G 100% | 161.554 G 101% | 160.071 G 100%
| disk IO (write) | | | |
| IOPS (op/sec) | 90 | 72 80% | 75 83% | 76 84%
| throughput (bytes/sec) | 5.925 M | 4.770 M 81% | 5.063 M 85% | 4.950 M 84%
| total (bytes) | 57.131 G | 57.874 G 101% | 58.616 G 103% | 57.134 G 100%
| | | | |
| max memory usage (bytes) | 0.295 G | 0.629 G 213% | 0.611 G 207% | 0.577 G 195%
| mean CPU usage | 70% | 96% | 83% | 83%
3.3.2 vs 3.4 (what is on main, with and without gc). Full Summary
| | 3.3.2 | 3.4 | 3.4_no_gc
| -- | -- | -- | --
| -- main metrics -- | | |
| CPU time elapsed | 162m16s | 192m21s 119% | 160m43s 99%
| Wall time elapsed | 232m28s | 231m55s 100% | 231m05s 99%
| TZ-transactions per sec | 1625.138 | 1370.961 84% | 1640.910 101%
| TZ-operations per sec | 2657.194 | 2241.601 84% | 2682.982 101%
| Context.add per sec | 21659.781 | 18272.123 84% | 21869.992 101%
| tail latency (1) | 0.559 s | 0.640 s 114% | 0.507 s 91%
| | | |
| -- resource usage -- | | |
| disk IO (total) | | |
| IOPS (op/sec) | 329_712 | 246_585 75% | 295_128 90%
| throughput (bytes/sec) | 23.995 M | 18.820 M 78% | 22.528 M 94%
| total (bytes) | 233.620 G | 217.206 G 93% | 217.225 G 93%
| disk IO (read) | | |
| IOPS (op/sec) | 329_623 | 246_510 75% | 295_037 90%
| throughput (bytes/sec) | 18.127 M | 13.870 M 77% | 16.603 M 92%
| total (bytes) | 176.489 G | 160.071 G 91% | 160.094 G 91%
| disk IO (write) | | |
| IOPS (op/sec) | 90 | 76 84% | 90 101%
| throughput (bytes/sec) | 5.868 M | 4.950 M 84% | 5.925 M 101%
| total (bytes) | 57.131 G | 57.134 G 100% | 57.131 G 100%
| | | |
| max memory usage (bytes) | 0.291 G | 0.577 G 198% | 0.295 G 101%
| mean CPU usage | 70% | 83% | 70%
I ran a fresh 3.2.2 benchmark to compare with 3.4's new IO. Fully Summary. See collapsed sections below for a few excerpted areas of the summary and light commentary.
I think the original motivation for opening this issue has been mostly addressed. We still have room for performance improvement, but lets follow up with specific issues.
| | 3.2.2 | 3.4_no_gc | 3.4_gc
| -- | -- | -- | --
| -- main metrics -- | | |
| CPU time elapsed | 167m28s | 160m43s 96% | 192m46s 115%
| Wall time elapsed | 227m14s | 231m05s 102% | 232m39s 102%
| TZ-transactions per sec | 1574.633 | 1640.910 104% | 1368.073 87%
| TZ-operations per sec | 2574.616 | 2682.982 104% | 2236.879 87%
| Context.add per sec | 20986.653 | 21869.992 104% | 18233.635 87%
| tail latency (1) | 0.214 s | 0.507 s 237% | 0.695 s 325%
| | | |
| -- resource usage -- | | |
| disk IO (total) | | |
| IOPS (op/sec) | 311_726 | 295_128 95% | 246_068 79%
| throughput (bytes/sec) | 97.310 M | 22.528 M 23% | 18.781 M 19%
| total (bytes) | 977.810 G | 217.225 G 22% | 217.208 G 22%
| disk IO (read) | | |
| IOPS (op/sec) | 311_619 | 295_037 95% | 245_993 79%
| throughput (bytes/sec) | 91.822 M | 16.603 M 18% | 13.840 M 15%
| total (bytes) | 922.661 G | 160.094 G 17% | 160.073 G 17%
| disk IO (write) | | |
| IOPS (op/sec) | 107 | 90 84% | 75 70%
| throughput (bytes/sec) | 5.488 M | 5.925 M 108% | 4.940 M 90%
| total (bytes) | 55.149 G | 57.131 G 104% | 57.135 G 104%
| | | |
| max memory usage (bytes) | 0.389 G | 0.295 G 76% | 0.576 G 148%
| mean CPU usage | 74% | 70% | 83%
Commit Times
The tail latency is noticeably higher for 3.4, but on average and at best, 3.4 appears to be an improvement. | | | cumu | share | min | max | avg
| | | | | | |
| commit duration (s) | 3.2.2 | 51min49s | 23% | 1.719 ms | 0.214 s | 21.445 ms
| | 3.4_no_gc | 39min10s 76% | 17% | 1.357 ms 79% | 0.507 s 237% | 16.207 ms 76%
| | 3.4_gc | 38min3s 73% | 16% | 1.278 ms 74% | 0.695 s 325% | 15.749 ms 73%
Memory
We are using more (for the main process -- still need to evaluate the child process properly) but are still within a good range. A notable stat is `minflt` increased significantly for the gc run vs no gc and 3.2.2. | | | total | min per block | max per block | avg per block | avg per sec
| | | | | | |
| rusage.maxrss | 3.2.2 | 0.389 G | 0 | 0.033 G | 0.000 G | 0.000 G
| | 3.4_no_gc | 0.295 G 76% | 0 | 0.068 G 204% | 0.000 G 56% | 0.000 G 55%
| | 3.4_gc | 0.576 G 148% | 0 | 0.042 G 127% | 0.000 G 166% | 0.000 G 162%
| rusage.minflt | 3.2.2 | 0.180 M | 0 | 30_115 | 1.239 | 13.178
| | 3.4_no_gc | 0.174 M 97% | 0 | 17_038 57% | 1.199 97% | 12.543 95%
| | 3.4_gc | 1.099 M 612% | 0 | 34_502 115% | 7.582 612% | 78.760 598%
| rusage.majflt | 3.2.2 | 17_047 | 0 | 583 | 0.118 | 1.250
| | 3.4_no_gc | 18_505 109% | 0 | 1_419 243% | 0.128 109% | 1.335 107%
| | 3.4_gc | 18_540 109% | 0 | 551 95% | 0.128 109% | 1.328 106%
| rusage.inblock | 3.2.2 | 374.055 M | 0 | 146_000 | 2579.692 | 27435.137
| | 3.4_no_gc | 409.958 M 110% | 0 | 161_792 111% | 2827.297 110% | 29567.132 108%
| | 3.4_gc | 325.805 M 87% | 0 | 114_520 78% | 2246.932 87% | 23340.405 85%
| rusage.oublock | 3.2.2 | 122.972 M | 200 | 7_184 | 848.081 | 9019.373
| | 3.4_no_gc | 126.837 M 103% | 200 100% | 10_520 146% | 874.735 103% | 9147.754 101%
| | 3.4_gc | 126.843 M 103% | 200 100% | 10_552 147% | 874.778 103% | 9086.907 101%
Disk
There is a significant reduction in disk bytes read and a slight increase in disk bytes written (although again this does not take into account the gc process).
| | | total | min per block | max per block | avg per block | avg per sec
| | | | | | |
| Disk bytes read | 3.2.2 | 922.661 G | 1.285 M | 131.194 M | 6.363 M | 67.673 M
| | 3.4_no_gc | 160.094 G 17% | 0.035 M 2.7% | 13.000 M 9.9% | 1.104 M 17% | 11.546 M 17%
| | 3.4_gc | 160.073 G 17% | 0.035 M 2.7% | 12.995 M 9.9% | 1.104 M 17% | 11.467 M 17%
| Disk bytes written | 3.2.2 | 55.149 G | 0.086 M | 2.768 M | 0.380 M | 4.045 M
| | 3.4_no_gc | 57.131 G 104% | 0.087 M 101% | 3.508 M 127% | 0.394 M 104% | 4.120 M 102%
| | 3.4_gc | 57.135 G 104% | 0.087 M 101% | 3.508 M 127% | 0.394 M 104% | 4.093 M 101%
| Disk bytes both | 3.2.2 | 977.810 G | 1.371 M | 131.434 M | 6.744 M | 71.718 M
| | 3.4_no_gc | 217.225 G 22% | 0.325 M 24% | 16.382 M 12% | 1.498 M 22% | 15.667 M 22%
| | 3.4_gc | 217.208 G 22% | 0.325 M 24% | 16.377 M 12% | 1.498 M 22% | 15.561 M 22%
| | | | | | |
| Disk reads | 3.2.2 | 3131.273 M | 2_583 | 609_148 | 21594.986 | 229663.594
| | 3.4_no_gc | 2844.912 M 91% | 776 30% | 256_758 42% | 19620.082 91% | 205181.690 89%
| | 3.4_gc | 2845.046 M 91% | 776 30% | 256_758 42% | 19621.006 91% | 203816.646 89%
| Disk writes | 3.2.2 | 1.076 M | 4 | 38 | 7.418 | 78.890
| | 3.4_no_gc | 0.871 M 81% | 4 100% | 12 32% | 6.010 81% | 62.847 80%
| | 3.4_gc | 0.871 M 81% | 4 100% | 12 32% | 6.010 81% | 62.428 79%
| Disk both | 3.2.2 | 3132.349 M | 2_587 | 609_154 | 21602.404 | 229742.484
| | 3.4_no_gc | 2845.783 M 91% | 780 30% | 256_770 42% | 19626.092 91% | 205244.537 89%
| | 3.4_gc | 2845.917 M 91% | 780 30% | 256_770 42% | 19627.016 91% | 203879.075 89%