Investigate using mmap instead of preads and pwrites

tomjridge commented 3 years ago

Just a quick comment: I wouldn't expect this to improve performance significantly.

tomjridge commented 3 years ago

I wrote a new version of Thomas' mmap-wip patch. It is https://github.com/tomjridge/index/tree/mmap-wip

I ran "make bench" on the master branch and on the mmap-wip branch. Results:

master branch: https://gist.github.com/tomjridge/a5782882d05e7de6341f2a3f65365100

mmap-wip branch: https://gist.github.com/tomjridge/1f2e5693baf52d71a7e766f802aa029c

These seem to indicate that mmap-wip is a bit quicker, eg: for master, replace_random is 37s, whilst with mmap-wip replace_random is 29s.

So, it does make a difference after all.

@icristescu @samoht

craigfe commented 3 years ago

Nice!

Would be good to get memory profiles for these runs too (likely via memtrace), to see what the trade-off is. (Perhaps a fair comparison at Tezos-like hyperparams should let the non-mmap patch have a larger log-size.)

Perhaps there's a follow-up perf win in having the codecs interact directly with the bigarray (rather than allocating all these intermediate strings)? What do you think?

tomjridge commented 3 years ago

Just briefly thinking about why these mmap benchmarks may be faster:

the OS might be a lot more aggressive in caching and reordering writes perhaps (I haven't looked at the tests to work out what is happening with fsyncs etc); this might lead to more errors of course, in the case that the machine crashes
perhaps a significant chunk of intermediate allocation has already gone
my machine has 64GB of memory, so perhaps the entire mmap was cached (which might not be possible on more constrained devices)

OK, I will try using memtrace

tomjridge commented 3 years ago

I haven't used memtrace, but just by eyeballing the system usage, the memory usage seems similar, but with mmap there is also high shared memory (for obvious reasons?), whereas without mmap there isn't.

samoht commented 3 years ago

The current implementation always reads a full page (even for short reads) to speed-up the interpolation search, as we try to get have syscall per find.

With mmap we do not need to do this, and so I expect intermediate allocation to be reduced if we also reduce this part of code.

tomjridge commented 3 years ago

Just to follow up: running irmin-master vs irmin-mmap, 100k trace, we have something like:

dune exec -- ./irmin/bench/irmin-pack/trace_stats.exe  pp -f master,master_stat_summary.json -f mmap,mmap_stat_summary.json
-- setups --
                | master                    | mmap
Hostname        | pc1156-nvmp3              | pc1156-nvmp3
Word Size       | 64 bits                   | 64 bits
Start Time      | 2021/08/24 13:09:22 (GMT) | 2021/08/24 13:27:24 (GMT)
Inode Config    | mls:32 bf:32 sh:256       | mls:32 bf:32 sh:256
Store Type      | pack                      | pack
Path Conversion | none                      | none

                         |  master   |      mmap
-- main metrics --       |           | 
CPU time elapsed         |    15m10s |    13m46s  91%
TZ-transactions per sec  |    85.687 |    94.460 110%
TZ-operations per sec    |  1549.842 |  1708.523 110%
Context.set per sec      |  7803.158 |  8602.085 110%
tail latency (1)         |   4.352 s |   3.256 s  75%
                         |           | 
-- resource usage --     |           | 
disk IO (total)          |           | 
  IOPS (op/sec)          |    92_624 |   102_107 110%
  throughput (bytes/sec) | 245.459 M | 270.604 M 110%
  total (bytes)          | 223.472 G | 223.483 G 100%
disk IO (read)           |           | 
  IOPS (op/sec)          |    92_123 |   101_555 110%
  throughput (bytes/sec) | 230.042 M | 253.608 M 110%
  total (bytes)          | 209.435 G | 209.446 G 100%
disk IO (write)          |           | 
  IOPS (op/sec)          |       500 |       552 110%
  throughput (bytes/sec) |  15.417 M |  16.996 M 110%
  total (bytes)          |  14.036 G |  14.036 G 100%
                         |           | 
max memory usage         |   1.466 G |   1.690 G 115%
mean CPU usage           |       96% |      100%     

 - (1) Longest Context.commit.
 - The "per sec" stats are calculated over CPU time.
 - "TZ-transactions" and "TZ-operations" are approximations.
 - "max memory usage" is the max size of OCaml's major heap.
 - "mean CPU usage" is inexact.

Ngoguey42 commented 3 years ago

Great! Can you include here the full pretty print?

tomjridge commented 3 years ago

Run 1:

   (python3_setup_venv) /tmp/l/github/irmin-variants/irmin-master $ make mk_trace_stats 
   dune exec -- ./irmin/bench/irmin-pack/trace_stats.exe  pp -f master,master_stat_summary.json -f mmap,mmap_stat_summary.json
   -- setups --
                   | master                    | mmap
   Hostname        | pc1156-nvmp3              | pc1156-nvmp3
   Word Size       | 64 bits                   | 64 bits
   Start Time      | 2021/08/24 12:16:39 (GMT) | 2021/08/24 12:34:58 (GMT)
   Inode Config    | mls:32 bf:32 sh:256       | mls:32 bf:32 sh:256
   Store Type      | pack                      | pack
   Path Conversion | none                      | none

                            |  master   |      mmap
   -- main metrics --       |           | 
   CPU time elapsed         |    15m33s |    14m13s  91%
   TZ-transactions per sec  |    83.627 |    91.441 109%
   TZ-operations per sec    |  1512.586 |  1653.920 109%
   Context.set per sec      |  7615.583 |  8327.170 109%
   tail latency (1)         |   3.962 s |   3.043 s  77%
                            |           | 
   -- resource usage --     |           | 
   disk IO (total)          |           | 
     IOPS (op/sec)          |    90_397 |    98_840 109%
     throughput (bytes/sec) | 239.569 M | 261.937 M 109%
     total (bytes)          | 223.481 G | 223.467 G 100%
   disk IO (read)           |           | 
     IOPS (op/sec)          |    89_908 |    98_305 109%
     throughput (bytes/sec) | 224.515 M | 245.488 M 109%
     total (bytes)          | 209.439 G | 209.433 G 100%
   disk IO (write)          |           | 
     IOPS (op/sec)          |       488 |       534 109%
     throughput (bytes/sec) |  15.054 M |  16.449 M 109%
     total (bytes)          |  14.043 G |  14.033 G 100%
                            |           | 
   max memory usage         |   1.356 G |   1.796 G 133%
   mean CPU usage           |       96% |       99%     

    - (1) Longest Context.commit.
    - The "per sec" stats are calculated over CPU time.
    - "TZ-transactions" and "TZ-operations" are approximations.
    - "max memory usage" is the max size of OCaml's major heap.
    - "mean CPU usage" is inexact.

   -- global --
                            |        | min per block |  max per block   |  avg per block  |    avg per sec
                            |        |               |                  |                 | 
   Add count                | master |        3      |     123_869      |     71.042      |      7279.342     
                            | mmap   |        3 100% |     123_869 100% |     71.042 100% |      8284.469 114%
   Remove count             | master |        0      |      15_385      |      2.253      |       230.819     
                            | mmap   |        0      |      15_385 100% |      2.253 100% |       262.691 114%
   Find count               | master |        2      |      92_013      |    233.931      |     23969.873     
                            | mmap   |        2 100% |      92_013 100% |    233.931 100% |     27279.619 114%
   Mem count                | master |        0      |      93_342      |     46.495      |      4764.178     
                            | mmap   |        0      |      93_342 100% |     46.495 100% |      5422.013 114%
   Mem_tree count           | master |        0      |          39      |     33.001      |      3381.455     
                            | mmap   |        0      |          39 100% |     33.001 100% |      3848.365 114%
   Copy count               | master |        0      |           7      |      0.004      |         0.407     
                            | mmap   |        0      |           7 100% |      0.004 100% |         0.463 114%
   Commit count             | master |        1      |           1      |      1.000      |       102.466     
                            | mmap   |        1 100% |           1 100% |      1.000 100% |       116.614 114%
                            |        |               |                  |                 | 
   Disk bytes read          | master |        0      |   648.682 M      |    2.094 M      |     214.603 M     
                            | mmap   |        0      |   659.031 M 102% |    2.094 M 100% |     244.229 M 114%
   Disk bytes written       | master |  0.000 M      |   694.260 M      |    0.140 M      |      14.389 M     
                            | mmap   |  0.000 M 100% |   703.552 M 101% |    0.140 M 100% |      16.365 M 114%
   Disk bytes both          | master |  0.000 M      |  1342.942 M      |    2.235 M      |     228.992 M     
                            | mmap   |  0.000 M 100% |  1362.583 M 101% |    2.235 M 100% |     260.594 M 114%
                            |        |               |                  |                 | 
   Disk reads               | master |        0      |     236_630      |    838.707      |     85938.641     
                            | mmap   |        0      |     236_630 100% |    838.675 100% |     97801.365 114%
   Disk writes              | master |        4      |       1_282      |      4.556      |       466.854     
                            | mmap   |        4 100% |       1_282 100% |      4.556 100% |       531.310 114%
   Disk both                | master |        4      |     236_684      |    843.263      |     86405.495     
                            | mmap   |        4 100% |     236_684 100% |    843.232 100% |     98332.675 114%
                            |        |               |                  |                 | 
   pack.finds               | master |        0      |     111_577      |    685.477      |     70237.845     
                            | mmap   |        0      |     111_577 100% |    685.477 100% |     79936.244 114%
   pack.cache_misses        | master |        0      |      47_625      |     42.727      |      4378.065     
                            | mmap   |        0      |      47_625 100% |     42.727 100% |      4982.586 114%
   pack.appended_hashes     | master |        0      |         100      |      0.065      |         6.680     
                            | mmap   |        0      |         100 100% |      0.065 100% |         7.602 114%
   pack.appended_offsets    | master |        0      |     251_219      |    738.911      |     75713.064     
                            | mmap   |        0      |     251_219 100% |    738.911 100% |     86167.479 114%
                            |        |               |                  |                 | 
   tree.contents_hash       | master |        0      |      62_693      |     45.148      |      4626.170     
                            | mmap   |        0      |      62_693 100% |     45.148 100% |      5264.948 114%
   tree.contents_find       | master |        0      |      47_605      |    122.656      |     12568.010     
                            | mmap   |        0      |      47_605 100% |    122.656 100% |     14303.394 114%
   tree.contents_add        | master |        0      |      36_134      |     40.382      |      4137.777     
                            | mmap   |        0      |      36_134 100% |     40.382 100% |      4709.119 114%
   tree.node_hash           | master |        0      |     166_818      |    125.913      |     12901.764     
                            | mmap   |        0      |     166_818 100% |    125.913 100% |     14683.232 114%
   tree.node_mem            | master |        0      |     166_778      |    125.023      |     12810.567     
                            | mmap   |        0      |     166_778 100% |    125.023 100% |     14579.443 114%
   tree.node_add            | master |        0      |     166_778      |    123.262      |     12630.101     
                            | mmap   |        0      |     166_778 100% |    123.262 100% |     14374.057 114%
   tree.node_find           | master |        0      |      48_984      |    222.303      |     22778.455     
                            | mmap   |        0      |      48_984 100% |    222.303 100% |     25923.690 114%
   tree.node_val_v          | master |        0      |     166_816      |      5.182      |       530.933     
                            | mmap   |        0      |     166_816 100% |      5.182 100% |       604.244 114%
   tree.node_val_find       | master |        0      |           0      |          0      |             0     
                            | mmap   |        0      |           0      |          0      |             0     
   tree.node_val_list       | master |        0      |         559      |      2.138      |       219.033     
                            | mmap   |        0      |         559 100% |      2.138 100% |       249.277 114%
                            |        |               |                  |                 | 
   index.cumu_data_bytes    | master |        0      |   699.599 M      |    111_935      |    11_469_508     
                            | mmap   |        0      | 40960.000 M  59x | 12_697_600 113x | 1_480_718_884 129x
                            |        |               |                  |                 | 
   gc.minor_words allocated | master |  0.020 M      |   692.339 M      |    1.782 M      |     182.589 M     
                            | mmap   |  0.020 M 100% |   692.331 M 100% |    1.777 M 100% |     207.204 M 113%
   gc.major_words allocated | master |        0      |    50.279 M      |    0.083 M      |       8.512 M     
                            | mmap   |        0      |    50.282 M 100% |    0.083 M 100% |       9.684 M 114%
   gc.minor_collections     | master |        0      |       2_651      |      6.801      |       696.821     
                            | mmap   |        0      |       2_651 100% |      6.781 100% |       790.761 113%
   gc.major_collections     | master |        0      |          17      |      0.005      |         0.544     
                            | mmap   |        0      |          17 100% |      0.005  99% |         0.612 113%

                                 |        |      min      |       max        |      avg
                                 |        |               |                  | 
   Block duration (s)            | master | 0.421 ms      |     3.965 s      |  9.759 ms     
                                 | mmap   | 0.273 ms  65% |     3.045 s  77% |  8.575 ms  88%
   Buildup duration (s)          | master | 0.233 ms      |     1.226 s      |  2.568 ms     
                                 | mmap   | 0.183 ms  78% |     1.180 s  96% |  2.452 ms  96%
   Commit duration (s)           | master | 0.102 ms      |     3.962 s      |  7.192 ms     
                                 | mmap   | 0.048 ms  47% |     3.043 s  77% |  6.123 ms  85%
                                 |        |               |                  | 
   Add duration (s)              | master | 0.193 µs      | 1040.174 ms      |  5.474 µs     
                                 | mmap   | 0.193 µs 100% | 1048.633 ms 101% |  5.528 µs 101%
   Remove duration (s)           | master | 0.302 µs      |    3.036 ms      |  3.670 µs     
                                 | mmap   | 0.319 µs 106% |    4.226 ms 139% |  3.559 µs  97%
   Find duration (s)             | master | 0.111 µs      | 1132.368 ms      |  5.404 µs     
                                 | mmap   | 0.112 µs 101% | 1113.487 ms  98% |  4.889 µs  90%
   Mem duration (s)              | master | 0.179 µs      |  494.301 ms      |  2.885 µs     
                                 | mmap   | 0.170 µs  95% | 1177.875 ms 238% |  3.177 µs 110%
   Mem_tree duration (s)         | master | 0.261 µs      |    9.690 ms      |  1.222 µs     
                                 | mmap   | 0.261 µs 100% | 1153.810 ms 119x |  1.682 µs 138%
   Copy duration (s)             | master | 0.995 µs      |    1.931 ms      | 13.547 µs     
                                 | mmap   | 0.943 µs  95% |    2.700 ms 140% | 19.146 µs 141%
   Unseen duration (s)           | master | 0.161 ms      |     1.221 s      |  0.730 ms     
                                 | mmap   | 0.150 ms  93% |     1.087 s  89% |  0.702 ms  96%
                                 |        |               |                  | 
   Major heap bytes after commit | master |  7.664 M      |  1355.502 M      | 756.088 M     
                                 | mmap   |  7.664 M 100% |  1796.334 M 133% | 764.842 M 101%
                                 |        |               |                  | 
   CPU Usage                     | master |      10%      |        116%      |       98%     
                                 | mmap   |       4%      |        126%      |      101%     

   -- evolution through blocks --
   Block played count *C                  |        | 0 (before) |      33500      |      67000      |  100000 (end)
   Blocks progress *C                     |        |     0%     |       34%       |       67%       |      100%
                                          |        |            |                 |                 | 
   Wall time elapsed *C                   | master |        0us |    2min49s      |    8min31s      |   16min15s     
                                          | mmap   |        0us |    2min30s  89% |    7min27s  87% |   14min17s  88%
   CPU time elapsed *C                    | master |        0us |    2min44s      |    8min14s      |   15min32s     
                                          | mmap   |        0us |    2min31s  92% |    7min27s  91% |   14min13s  91%
   CPU Usage *LA                          | master |        n/a |        98%      |        98%      |        98%     
                                          | mmap   |        n/a |       102%      |       101%      |       101%     
                                          |        |            |                 |                 | 
   Approx. TZ-transaction count *C        | master |          0 |     25_109      |     40_189      |     78_011     
                                          | mmap   |          0 |     25_109 100% |     40_189 100% |     78_011 100%
   Approx. TZ-operations count *C         | master |          0 |    230_333      |    763_445      |  1_411_012     
                                          | mmap   |          0 |    230_333 100% |    763_445 100% |  1_411_012 100%
   Op count *C                            | master |    0.000 M |   10.824 M      |   24.081 M      |   38.873 M     
                                          | mmap   |    0.000 M |   10.824 M 100% |   24.081 M 100% |   38.873 M 100%
                                          |        |            |                 |                 | 
   Commit per sec *LA *N                  | master |        n/a |    131.860      |     86.502      |     63.841     
                                          | mmap   |        n/a |    163.528 124% |    104.214 120% |     70.967 111%
   Add per sec *LA *N                     | master |        n/a |   8786.628      |   7659.356      |   6517.349     
                                          | mmap   |        n/a |  10896.871 124% |   9227.759 120% |   7244.766 111%
   Remove per sec *LA *N                  | master |        n/a |    371.276      |    148.937      |    108.852     
                                          | mmap   |        n/a |    460.444 124% |    179.435 120% |    121.001 111%
   Find per sec *LA *N                    | master |        n/a |  31318.458      |  22727.227      |  18051.253     
                                          | mmap   |        n/a |  38840.068 124% |  27381.072 120% |  20065.999 111%
   Mem per sec *LA *N                     | master |        n/a |   4930.279      |   4219.293      |   3904.668     
                                          | mmap   |        n/a |   6114.361 124% |   5083.275 120% |   4340.478 111%
   Mem_tree per sec *LA *N                | master |        n/a |   4351.486      |   2854.551      |   2106.769     
                                          | mmap   |        n/a |   5396.562 124% |   3439.076 120% |   2341.910 111%
   Copy per sec *LA *N                    | master |        n/a |      0.489      |      0.327      |      0.245     
                                          | mmap   |        n/a |      0.607 124% |      0.394 120% |      0.272 111%
                                          |        |            |                 |                 | 
   Add count per block *LA                | master |        n/a |     66.636      |     88.546      |    102.086     
                                          | mmap   |        n/a |     66.636 100% |     88.546 100% |    102.086 100%
   Remove count per block *LA             | master |        n/a |      2.816      |      1.722      |      1.705     
                                          | mmap   |        n/a |      2.816 100% |      1.722 100% |      1.705 100%
   Find count per block *LA               | master |        n/a |    237.513      |    262.738      |    282.751     
                                          | mmap   |        n/a |    237.513 100% |    262.738 100% |    282.751 100%
   Mem count per block *LA                | master |        n/a |     37.390      |     48.777      |     61.162     
                                          | mmap   |        n/a |     37.390 100% |     48.777 100% |     61.162 100%
   Mem_tree count per block *LA           | master |        n/a |     33.001      |     33.000      |     33.000     
                                          | mmap   |        n/a |     33.001 100% |     33.000 100% |     33.000 100%
   Copy count per block *LA               | master |        n/a |      0.004      |      0.004      |      0.004     
                                          | mmap   |        n/a |      0.004 100% |      0.004 100% |      0.004 100%
                                          |        |            |                 |                 | 
   Block duration *LA                     | master |        n/a |   7.584 ms      |  11.560 ms      |  15.664 ms     
                                          | mmap   |        n/a |   6.115 ms  81% |   9.596 ms  83% |  14.091 ms  90%
   Buildup duration *LA                   | master |        n/a |   2.600 ms      |   3.222 ms      |   3.899 ms     
                                          | mmap   |        n/a |   2.072 ms  80% |   2.718 ms  84% |   3.402 ms  87%
   Commit duration *LA                    | master |        n/a |   4.984 ms      |   8.338 ms      |  11.765 ms     
                                          | mmap   |        n/a |   4.043 ms  81% |   6.878 ms  82% |  10.689 ms  91%
                                          |        |            |                 |                 | 
   Add duration *LA                       | master |        n/a |   5.196 µs      |   5.810 µs      |   6.468 µs     
                                          | mmap   |        n/a |   4.574 µs  88% |   5.539 µs  95% |   6.232 µs  96%
   Remove duration *LA                    | master |        n/a |   7.564 µs      |  12.941 µs      |   5.316 µs     
                                          | mmap   |        n/a |   5.481 µs  72% |   4.680 µs  36% |   8.541 µs 161%
   Find duration *LA                      | master |        n/a |   4.801 µs      |   6.341 µs      |   7.713 µs     
                                          | mmap   |        n/a |   3.897 µs  81% |   5.138 µs  81% |   5.955 µs  77%
   Mem duration *LA                       | master |        n/a |   2.573 µs      |   2.679 µs      |   2.555 µs     
                                          | mmap   |        n/a |   2.382 µs  93% |   3.630 µs 135% |   2.630 µs 103%
   Mem_tree duration *LA                  | master |        n/a |   1.086 µs      |   1.371 µs      |   1.477 µs     
                                          | mmap   |        n/a |   6.055 µs 557% |   1.293 µs  94% |   1.574 µs 107%
   Copy duration *LA                      | master |        n/a |  19.979 µs      |   8.615 µs      |   7.380 µs     
                                          | mmap   |        n/a |  11.172 µs  56% |  12.922 µs 150% |   7.141 µs  97%
   Checkout duration *LA                  | master |        n/a |   2.205 µs      |   2.616 µs      |   2.303 µs     
                                          | mmap   |        n/a |   2.290 µs 104% |   2.502 µs  96% |   2.921 µs 127%
                                          |        |            |                 |                 | 
   Disk bytes    read *C                  | master |    0.000 G |   21.951 G      |   99.735 G      |  209.439 G     
                                          | mmap   |    0.000 G |   21.939 G 100% |   99.718 G 100% |  209.433 G 100%
   Disk bytes written *C                  | master |    0.000 G |    0.678 G      |    4.604 G      |   14.043 G     
                                          | mmap   |    0.000 G |    0.673 G  99% |    4.589 G 100% |   14.033 G 100%
   Disk bytes    both *C                  | master |    0.000 G |   22.629 G      |  104.339 G      |  223.481 G     
                                          | mmap   |    0.000 G |   22.612 G 100% |  104.307 G 100% |  223.467 G 100%
   Disk bytes read    per block *LA       | master |        n/a |  1_288_756      |  2_653_148      |  3_548_450     
                                          | mmap   |        n/a |  1_288_420 100% |  2_649_875 100% |  3_546_779 100%
   Disk bytes written per block *LA       | master |        n/a |     33_738      |    113_423      |    369_084     
                                          | mmap   |        n/a |     33_628 100% |    110_611  98% |    367_640 100%
   Disk bytes both    per block *LA       | master |        n/a |  1_322_493      |  2_766_571      |  3_917_533     
                                          | mmap   |        n/a |  1_322_049 100% |  2_760_486 100% |  3_914_419 100%
   Disk bytes read    per sec *LA *N      | master |        n/a |  169.935 M      |  229.501 M      |  226.538 M     
                                          | mmap   |        n/a |  210.693 M 124% |  276.155 M 120% |  251.704 M 111%
   Disk bytes written per sec *LA *N      | master |        n/a |    4.449 M      |    9.811 M      |   23.563 M     
                                          | mmap   |        n/a |    5.499 M 124% |   11.527 M 117% |   26.090 M 111%
   Disk bytes both    per sec *LA *N      | master |        n/a |  174.384 M      |  239.313 M      |  250.101 M     
                                          | mmap   |        n/a |  216.192 M 124% |  287.682 M 120% |  277.794 M 111%
                                          |        |            |                 |                 | 
   Disk read  count *C                    | master |    0.000 M |   10.568 M      |   42.653 M      |   83.871 M     
                                          | mmap   |    0.000 M |   10.565 M 100% |   42.650 M 100% |   83.868 M 100%
   Disk write count *C                    | master |          5 |    162_107      |    311_943      |    455_625     
                                          | mmap   |          5 |    162_099 100% |    311_929 100% |    455_619 100%
   Disk both  count *C                    | master |    0.000 M |   10.730 M      |   42.965 M      |   84.326 M     
                                          | mmap   |    0.000 M |   10.727 M 100% |   42.962 M 100% |   84.323 M 100%
   Disk read  count per block *LA         | master |        n/a |    637.082      |   1124.114      |   1426.092     
                                          | mmap   |        n/a |    637.081 100% |   1124.106 100% |   1426.088 100%
   Disk write count per block *LA         | master |        n/a |      4.517      |      4.354      |      4.244     
                                          | mmap   |        n/a |      4.517 100% |      4.351 100% |      4.243 100%
   Disk both  count per block *LA         | master |        n/a |    641.599      |   1128.467      |   1430.336     
                                          | mmap   |        n/a |    641.598 100% |   1128.457 100% |   1430.331 100%
   Disk read  count per sec *LA *N        | master |        n/a |     84_006      |     97_238      |     91_044     
                                          | mmap   |        n/a |    104_181 124% |    117_148 120% |    101_205 111%
   Disk write count per sec *LA *N        | master |        n/a |        596      |        377      |        271     
                                          | mmap   |        n/a |        739 124% |        453 120% |        301 111%
   Disk both  count per sec *LA *N        | master |        n/a |     84_601      |     97_614      |     91_315     
                                          | mmap   |        n/a |    104_919 124% |    117_601 120% |    101_506 111%
                                          |        |            |                 |                 | 
   pack.finds per block *LA               | master |        n/a |    553.313      |    789.198      |    977.697     
                                          | mmap   |        n/a |    553.313 100% |    789.198 100% |    977.697 100%
   pack.cache_misses per block *LA        | master |        n/a |     47.450      |     59.519      |     69.168     
                                          | mmap   |        n/a |     47.450 100% |     59.519 100% |     69.168 100%
   pack.appended_hashes per block *LA     | master |        n/a |  0.074_490      |  0.032_069      |  0.040_356     
                                          | mmap   |        n/a |  0.074_490 100% |  0.032_069 100% |  0.040_356 100%
   pack.appended_offsets per block *LA    | master |        n/a |    510.293      |    908.002      |   1179.177     
                                          | mmap   |        n/a |    510.293 100% |    908.002 100% |   1179.177 100%
                                          |        |            |                 |                 | 
   tree.contents_hash per block *LA       | master |        n/a |     36.548      |     55.671      |     65.147     
                                          | mmap   |        n/a |     36.548 100% |     55.671 100% |     65.147 100%
   tree.contents_find per block *LA       | master |        n/a |    119.491      |    149.254      |    165.504     
                                          | mmap   |        n/a |    119.491 100% |    149.254 100% |    165.504 100%
   tree.contents_add per block *LA        | master |        n/a |     34.110      |     49.757      |     58.392     
                                          | mmap   |        n/a |     34.110 100% |     49.757 100% |     58.392 100%
   tree.node_hash per block *LA           | master |        n/a |    101.886      |    152.333      |    179.619     
                                          | mmap   |        n/a |    101.886 100% |    152.333 100% |    179.619 100%
   tree.node_mem per block *LA            | master |        n/a |    101.111      |    151.813      |    179.152     
                                          | mmap   |        n/a |    101.111 100% |    151.813 100% |    179.152 100%
   tree.node_add per block *LA            | master |        n/a |    100.309      |    149.101      |    176.012     
                                          | mmap   |        n/a |    100.309 100% |    149.101 100% |    176.012 100%
   tree.node_find per block *LA           | master |        n/a |    202.930      |    247.157      |    273.691     
                                          | mmap   |        n/a |    202.930 100% |    247.157 100% |    273.691 100%
   tree.node_val_v per block *LA          | master |        n/a |  3.410_123      |  1.834_733      |  1.704_790     
                                          | mmap   |        n/a |  3.410_123 100% |  1.834_733 100% |  1.704_790 100%
   tree.node_val_find per block *LA       | master |        n/a |          0      |          0      |          0     
                                          | mmap   |        n/a |          0      |          0      |          0     
   tree.node_val_list per block *LA       | master |        n/a |  1.935_643      |  1.434_413      |  1.473_389     
                                          | mmap   |        n/a |  1.935_643 100% |  1.434_413 100% |  1.473_389 100%
                                          |        |            |                 |                 | 
   index.nb_merge *C                      | master |          0 |          5      |         17      |         32     
                                          | mmap   |          0 |          5 100% |         17 100% |         32 100%
   index.cumu_data_bytes *C               | master |    0.000 G |    0.226 G      |    3.069 G      |   11.194 G     
                                          | mmap   |    0.000 G |  163.840 G 726x |  655.360 G 214x | 1269.760 G 113x
   index.cumu_data_bytes per block *LA    | master |        n/a |    0.012 M      |    0.076 M      |    0.325 M     
                                          | mmap   |        n/a |    5.658 M 460x |    8.824 M 116x |   19.261 M  59x
                                          |        |            |                 |                 | 
   gc.minor_words allocated *C            | master |    0.001 G |   34.136 G      |   96.495 G      |  178.196 G     
                                          | mmap   |    0.001 G |   34.067 G 100% |   96.228 G 100% |  177.685 G 100%
   gc.minor_words allocated per block *LA | master |        n/a |  1_377_921      |  2_071_272      |  2_787_234     
                                          | mmap   |        n/a |  1_373_935 100% |  2_062_582 100% |  2_777_726 100%
   gc.promoted_words *C                   | master |    0.218 M | 1653.437 M      | 4513.140 M      | 8038.362 M     
                                          | mmap   |    0.218 M | 1652.890 M 100% | 4512.367 M 100% | 8034.979 M 100%
   gc.major_words allocated *C            | master |    0.644 M | 1697.908 M      | 4653.838 M      | 8308.228 M     
                                          | mmap   |    0.644 M | 1697.362 M 100% | 4653.067 M 100% | 8304.847 M 100%
   gc.major_words allocated per block *LA | master |        n/a |     69_119      |     98_428      |    121_834     
                                          | mmap   |        n/a |     69_089 100% |     98_190 100% |    121_928 100%
   gc.minor_collections *C                | master |          4 |    130_295      |    368_274      |    680_057     
                                          | mmap   |          4 |    130_033 100% |    367_255 100% |    678_105 100%
   gc.minor_collections per block *LA     | master |        n/a |      5.259      |      7.904      |     10.636     
                                          | mmap   |        n/a |      5.243 100% |      7.871 100% |     10.600 100%
   gc.major_collections *C                | master |          1 |        151      |        331      |        532     
                                          | mmap   |          1 |        150  99% |        324  98% |        526  99%
   gc.major_collections per block *LA     | master |        n/a |  4.588e-03      |  5.001e-03      |  6.517e-03     
                                          | mmap   |        n/a |  3.423e-03  75% |  4.711e-03  94% |  6.888e-03 106%
   gc.compactions *C                      | master |          0 |          3      |          9      |         17     
                                          | mmap   |          0 |          3 100% |          9 100% |         17 100%
                                          |        |            |                 |                 | 
   gc.major heap bytes top *C             | master |    7.664 M | 1284.428 M      | 1355.502 M      | 1355.502 M     
                                          | mmap   |    7.664 M | 1390.957 M 108% | 1671.008 M 123% | 1796.334 M 133%
   gc.major heap bytes *LA                | master |    7.664 M | 1106.817 M      | 1024.950 M      |  586.015 M     
                                          | mmap   |    7.664 M | 1083.953 M  98% | 1027.056 M 100% |  529.424 M  90%
                                          |        |            |                 |                 | 
   index_data bytes *S                    | master |    0.000 G |    0.090 G      |    0.361 G      |    0.700 G     
                                          | mmap   |    0.000 G |   40.960 G 454x |   40.960 G 113x |   40.960 G  59x
   index_data bytes per block *LA         | master |        n/a |      3_109      |      4_847      |     10_581     
                                          | mmap   |        n/a |          2 0.1% |          0 0.0% |          0 0.0%
   store_pack bytes *S                    | master |    0.000 G |    0.239 G      |    0.760 G      |    1.422 G     
                                          | mmap   |   40.960 G |   40.960 G 171x |   40.960 G  54x |   40.960 G  29x
   store_pack bytes per block *LA         | master |        n/a |     10_414      |     17_367      |     21_581     
                                          | mmap   |        n/a |          0   0% |          0   0% |          0   0%
   index_log bytes *S                     | master |    0.000 G |    0.023 G      |    0.023 G      |    0.023 G     
                                          | mmap   |   40.960 G |   40.960 G 2e3x |   40.960 G 2e3x |   40.960 G 2e3x
   index_log_async *S                     | master |    0.000 G |    0.015 G      |    0.020 G      |    0.010 G     
                                          | mmap   |    0.000 G |   40.960 G 3e3x |   40.960 G 2e3x |   40.960 G 4e3x
   store_dict bytes *S                    | master |    0.000 G |    0.002 G      |    0.002 G      |    0.002 G     
                                          | mmap   |   40.960 G |   40.960 G 2e4x |   40.960 G 2e4x |   40.960 G 2e4x
                                          |        |            |                 |                 | 
   /data/contracts/index *S               | master |        n/a |          4      |          4      |          4     
                                          | mmap   |        n/a |          4 100% |          4 100% |          4 100%
   /data/big_maps/index *S                | master |        n/a |          0      |          0      |          0     
                                          | mmap   |        n/a |          0      |          0      |          0     
   /data/rolls/index *S                   | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%
   /data/rolls/owner/current *S           | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%
   /data/commitments *S                   | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%
   /data/contracts/index/ed25519 *S       | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%
   /data/contracts/index/originated *S    | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%

   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 1250.01 blocks, half of the past is forgotten.
    *S: Size. E.g. directory entries, file bytes. No smoothing.
    *N: Very noisy.

Run 2:

   dune exec -- ./irmin/bench/irmin-pack/trace_stats.exe  pp -f master,master_stat_summary.json -f mmap,mmap_stat_summary.json
   -- setups --
                   | master                    | mmap
   Hostname        | pc1156-nvmp3              | pc1156-nvmp3
   Word Size       | 64 bits                   | 64 bits
   Start Time      | 2021/08/24 13:09:22 (GMT) | 2021/08/24 13:27:24 (GMT)
   Inode Config    | mls:32 bf:32 sh:256       | mls:32 bf:32 sh:256
   Store Type      | pack                      | pack
   Path Conversion | none                      | none

                            |  master   |      mmap
   -- main metrics --       |           | 
   CPU time elapsed         |    15m10s |    13m46s  91%
   TZ-transactions per sec  |    85.687 |    94.460 110%
   TZ-operations per sec    |  1549.842 |  1708.523 110%
   Context.set per sec      |  7803.158 |  8602.085 110%
   tail latency (1)         |   4.352 s |   3.256 s  75%
                            |           | 
   -- resource usage --     |           | 
   disk IO (total)          |           | 
     IOPS (op/sec)          |    92_624 |   102_107 110%
     throughput (bytes/sec) | 245.459 M | 270.604 M 110%
     total (bytes)          | 223.472 G | 223.483 G 100%
   disk IO (read)           |           | 
     IOPS (op/sec)          |    92_123 |   101_555 110%
     throughput (bytes/sec) | 230.042 M | 253.608 M 110%
     total (bytes)          | 209.435 G | 209.446 G 100%
   disk IO (write)          |           | 
     IOPS (op/sec)          |       500 |       552 110%
     throughput (bytes/sec) |  15.417 M |  16.996 M 110%
     total (bytes)          |  14.036 G |  14.036 G 100%
                            |           | 
   max memory usage         |   1.466 G |   1.690 G 115%
   mean CPU usage           |       96% |      100%     

    - (1) Longest Context.commit.
    - The "per sec" stats are calculated over CPU time.
    - "TZ-transactions" and "TZ-operations" are approximations.
    - "max memory usage" is the max size of OCaml's major heap.
    - "mean CPU usage" is inexact.

   -- global --
                            |        | min per block |  max per block   |  avg per block  |    avg per sec
                            |        |               |                  |                 | 
   Add count                | master |        3      |     123_869      |     71.042      |      7454.733     
                            | mmap   |        3 100% |     123_869 100% |     71.042 100% |      8559.506 115%
   Remove count             | master |        0      |      15_385      |      2.253      |       236.381     
                            | mmap   |        0      |      15_385 100% |      2.253 100% |       271.412 115%
   Find count               | master |        2      |      92_013      |    233.931      |     24547.413     
                            | mmap   |        2 100% |      92_013 100% |    233.931 100% |     28185.278 115%
   Mem count                | master |        0      |      93_342      |     46.495      |      4878.968     
                            | mmap   |        0      |      93_342 100% |     46.495 100% |      5602.019 115%
   Mem_tree count           | master |        0      |          39      |     33.001      |      3462.930     
                            | mmap   |        0      |          39 100% |     33.001 100% |      3976.127 115%
   Copy count               | master |        0      |           7      |      0.004      |         0.417     
                            | mmap   |        0      |           7 100% |      0.004 100% |         0.478 115%
   Commit count             | master |        1      |           1      |      1.000      |       104.935     
                            | mmap   |        1 100% |           1 100% |      1.000 100% |       120.486 115%
                            |        |               |                  |                 | 
   Disk bytes read          | master |        0      |   650.932 M      |    2.094 M      |     219.770 M     
                            | mmap   |        0      |   656.331 M 101% |    2.094 M 100% |     252.352 M 115%
   Disk bytes written       | master |  0.000 M      |   694.260 M      |    0.140 M      |      14.729 M     
                            | mmap   |  0.000 M 100% |   700.455 M 101% |    0.140 M 100% |      16.912 M 115%
   Disk bytes both          | master |  0.000 M      |  1345.192 M      |    2.235 M      |     234.499 M     
                            | mmap   |  0.000 M 100% |  1356.785 M 101% |    2.235 M 100% |     269.264 M 115%
                            |        |               |                  |                 | 
   Disk reads               | master |        0      |     236_630      |    838.711      |     88009.728     
                            | mmap   |        0      |     236_629 100% |    838.711 100% |    101052.541 115%
   Disk writes              | master |        4      |       1_282      |      4.556      |       478.098     
                            | mmap   |        4 100% |       1_282 100% |      4.556 100% |       548.951 115%
   Disk both                | master |        4      |     236_684      |    843.267      |     88487.826     
                            | mmap   |        4 100% |     236_683 100% |    843.267 100% |    101601.492 115%
                            |        |               |                  |                 | 
   pack.finds               | master |        0      |     111_577      |    685.477      |     71930.183     
                            | mmap   |        0      |     111_577 100% |    685.477 100% |     82590.055 115%
   pack.cache_misses        | master |        0      |      47_625      |     42.727      |      4483.552     
                            | mmap   |        0      |      47_625 100% |     42.727 100% |      5148.003 115%
   pack.appended_hashes     | master |        0      |         100      |      0.065      |         6.841     
                            | mmap   |        0      |         100 100% |      0.065 100% |         7.854 115%
   pack.appended_offsets    | master |        0      |     251_219      |    738.911      |     77537.324     
                            | mmap   |        0      |     251_219 100% |    738.911 100% |     89028.160 115%
                            |        |               |                  |                 | 
   tree.contents_hash       | master |        0      |      62_693      |     45.148      |      4737.634     
                            | mmap   |        0      |      62_693 100% |     45.148 100% |      5439.740 115%
   tree.contents_find       | master |        0      |      47_605      |    122.656      |     12870.829     
                            | mmap   |        0      |      47_605 100% |    122.656 100% |     14778.253 115%
   tree.contents_add        | master |        0      |      36_134      |     40.382      |      4237.474     
                            | mmap   |        0      |      36_134 100% |     40.382 100% |      4865.457 115%
   tree.node_hash           | master |        0      |     166_818      |    125.913      |     13212.624     
                            | mmap   |        0      |     166_818 100% |    125.913 100% |     15170.701 115%
   tree.node_mem            | master |        0      |     166_778      |    125.023      |     13119.230     
                            | mmap   |        0      |     166_778 100% |    125.023 100% |     15063.467 115%
   tree.node_add            | master |        0      |     166_778      |    123.262      |     12934.415     
                            | mmap   |        0      |     166_778 100% |    123.262 100% |     14851.263 115%
   tree.node_find           | master |        0      |      48_984      |    222.303      |     23327.288     
                            | mmap   |        0      |      48_984 100% |    222.303 100% |     26784.333 115%
   tree.node_val_v          | master |        0      |     166_816      |      5.182      |       543.726     
                            | mmap   |        0      |     166_816 100% |      5.182 100% |       624.304 115%
   tree.node_val_find       | master |        0      |           0      |          0      |             0     
                            | mmap   |        0      |           0      |          0      |             0     
   tree.node_val_list       | master |        0      |         559      |      2.138      |       224.310     
                            | mmap   |        0      |         559 100% |      2.138 100% |       257.552 115%
                            |        |               |                  |                 | 
   index.cumu_data_bytes    | master |        0      |   699.599 M      |    111_935      |    11_745_859     
                            | mmap   |        0      | 40960.000 M  59x | 12_697_600 113x | 1_529_877_394 130x
                            |        |               |                  |                 | 
   gc.minor_words allocated | master |  0.020 M      |   692.339 M      |    1.782 M      |     186.986 M     
                            | mmap   |  0.020 M 100% |   692.331 M 100% |    1.777 M 100% |     214.087 M 114%
   gc.major_words allocated | master |        0      |    50.279 M      |    0.083 M      |       8.721 M     
                            | mmap   |        0      |    50.282 M 100% |    0.083 M 100% |      10.009 M 115%
   gc.minor_collections     | master |        0      |       2_651      |      6.800      |       713.599     
                            | mmap   |        0      |       2_651 100% |      6.781 100% |       817.025 114%
   gc.major_collections     | master |        0      |          17      |      0.005      |         0.556     
                            | mmap   |        0      |          17 100% |      0.005 100% |         0.636 114%

                                 |        |      min      |       max        |      avg
                                 |        |               |                  | 
   Block duration (s)            | master | 0.364 ms      |     4.354 s      |  9.530 ms     
                                 | mmap   | 0.284 ms  78% |     3.258 s  75% |  8.300 ms  87%
   Buildup duration (s)          | master | 0.177 ms      |     1.187 s      |  2.458 ms     
                                 | mmap   | 0.186 ms 105% |     1.125 s  95% |  2.358 ms  96%
   Commit duration (s)           | master | 0.105 ms      |     4.352 s      |  7.072 ms     
                                 | mmap   | 0.047 ms  44% |     3.256 s  75% |  5.942 ms  84%
                                 |        |               |                  | 
   Add duration (s)              | master | 0.193 µs      | 1009.661 ms      |  5.118 µs     
                                 | mmap   | 0.193 µs 100% | 1091.276 ms 108% |  5.474 µs 107%
   Remove duration (s)           | master | 0.323 µs      |    4.292 ms      |  3.792 µs     
                                 | mmap   | 0.300 µs  93% |    4.245 ms  99% |  3.703 µs  98%
   Find duration (s)             | master | 0.112 µs      | 1056.777 ms      |  5.363 µs     
                                 | mmap   | 0.111 µs  99% | 1110.698 ms 105% |  4.779 µs  89%
   Mem duration (s)              | master | 0.177 µs      |  172.857 ms      |  2.752 µs     
                                 | mmap   | 0.171 µs  97% |  384.962 ms 223% |  2.809 µs 102%
   Mem_tree duration (s)         | master | 0.262 µs      |    4.792 ms      |  1.185 µs     
                                 | mmap   | 0.260 µs  99% |    6.681 ms 139% |  1.218 µs 103%
   Copy duration (s)             | master | 0.929 µs      |    0.255 ms      |  8.291 µs     
                                 | mmap   | 0.895 µs  96% |    0.219 ms  86% |  8.961 µs 108%
   Unseen duration (s)           | master | 0.162 ms      |     1.065 s      |  0.662 ms     
                                 | mmap   | 0.149 ms  92% |     1.121 s 105% |  0.670 ms 101%
                                 |        |               |                  | 
   Major heap bytes after commit | master |  7.664 M      |  1465.668 M      | 758.879 M     
                                 | mmap   |  7.664 M 100% |  1690.018 M 115% | 791.469 M 104%
                                 |        |               |                  | 
   CPU Usage                     | master |      15%      |        115%      |       98%     
                                 | mmap   |      11%      |        122%      |      101%     

   -- evolution through blocks --
   Block played count *C                  |        | 0 (before) |      33500      |      67000      |  100000 (end)
   Blocks progress *C                     |        |     0%     |       34%       |       67%       |      100%
                                          |        |            |                 |                 | 
   Wall time elapsed *C                   | master |        0us |    2min45s      |    8min22s      |   15min52s     
                                          | mmap   |        0us |    2min31s  92% |    7min25s  89% |   13min49s  87%
   CPU time elapsed *C                    | master |        0us |    2min40s      |     8min6s      |   15min10s     
                                          | mmap   |        0us |    2min32s  95% |    7min26s  92% |   13min45s  91%
   CPU Usage *LA                          | master |        n/a |        99%      |        98%      |        98%     
                                          | mmap   |        n/a |       102%      |       101%      |       101%     
                                          |        |            |                 |                 | 
   Approx. TZ-transaction count *C        | master |          0 |     25_109      |     40_189      |     78_011     
                                          | mmap   |          0 |     25_109 100% |     40_189 100% |     78_011 100%
   Approx. TZ-operations count *C         | master |          0 |    230_333      |    763_445      |  1_411_012     
                                          | mmap   |          0 |    230_333 100% |    763_445 100% |  1_411_012 100%
   Op count *C                            | master |    0.000 M |   10.824 M      |   24.081 M      |   38.873 M     
                                          | mmap   |    0.000 M |   10.824 M 100% |   24.081 M 100% |   38.873 M 100%
                                          |        |            |                 |                 | 
   Commit per sec *LA *N                  | master |        n/a |    139.636      |     89.377      |     66.211     
                                          | mmap   |        n/a |    164.115 118% |    104.741 117% |     78.393 118%
   Add per sec *LA *N                     | master |        n/a |   9304.824      |   7913.954      |   6759.197     
                                          | mmap   |        n/a |  10935.964 118% |   9274.371 117% |   8002.864 118%
   Remove per sec *LA *N                  | master |        n/a |    393.173      |    153.888      |    112.892     
                                          | mmap   |        n/a |    462.096 118% |    180.341 117% |    133.663 118%
   Find per sec *LA *N                    | master |        n/a |  33165.483      |  23482.683      |  18721.105     
                                          | mmap   |        n/a |  38979.407 118% |  27519.381 117% |  22165.721 118%
   Mem per sec *LA *N                     | master |        n/a |   5221.045      |   4359.542      |   4049.564     
                                          | mmap   |        n/a |   6136.297 118% |   5108.952 117% |   4794.669 118%
   Mem_tree per sec *LA *N                | master |        n/a |   4608.117      |   2949.436      |   2184.947     
                                          | mmap   |        n/a |   5415.922 118% |   3456.448 117% |   2586.970 118%
   Copy per sec *LA *N                    | master |        n/a |      0.518      |      0.338      |      0.254     
                                          | mmap   |        n/a |      0.609 118% |      0.396 117% |      0.301 118%
                                          |        |            |                 |                 | 
   Add count per block *LA                | master |        n/a |     66.636      |     88.546      |    102.086     
                                          | mmap   |        n/a |     66.636 100% |     88.546 100% |    102.086 100%
   Remove count per block *LA             | master |        n/a |      2.816      |      1.722      |      1.705     
                                          | mmap   |        n/a |      2.816 100% |      1.722 100% |      1.705 100%
   Find count per block *LA               | master |        n/a |    237.513      |    262.738      |    282.751     
                                          | mmap   |        n/a |    237.513 100% |    262.738 100% |    282.751 100%
   Mem count per block *LA                | master |        n/a |     37.390      |     48.777      |     61.162     
                                          | mmap   |        n/a |     37.390 100% |     48.777 100% |     61.162 100%
   Mem_tree count per block *LA           | master |        n/a |     33.001      |     33.000      |     33.000     
                                          | mmap   |        n/a |     33.001 100% |     33.000 100% |     33.000 100%
   Copy count per block *LA               | master |        n/a |      0.004      |      0.004      |      0.004     
                                          | mmap   |        n/a |      0.004 100% |      0.004 100% |      0.004 100%
                                          |        |            |                 |                 | 
   Block duration *LA                     | master |        n/a |   7.161 ms      |  11.189 ms      |  15.103 ms     
                                          | mmap   |        n/a |   6.093 ms  85% |   9.547 ms  85% |  12.756 ms  84%
   Buildup duration *LA                   | master |        n/a |   2.539 ms      |   2.922 ms      |   3.469 ms     
                                          | mmap   |        n/a |   1.934 ms  76% |   2.686 ms  92% |   3.138 ms  90%
   Commit duration *LA                    | master |        n/a |   4.623 ms      |   8.267 ms      |  11.634 ms     
                                          | mmap   |        n/a |   4.159 ms  90% |   6.861 ms  83% |   9.618 ms  83%
                                          |        |            |                 |                 | 
   Add duration *LA                       | master |        n/a |   4.636 µs      |   5.545 µs      |   5.756 µs     
                                          | mmap   |        n/a |   4.616 µs 100% |   5.376 µs  97% |   5.442 µs  95%
   Remove duration *LA                    | master |        n/a |   8.760 µs      |   6.717 µs      |   7.437 µs     
                                          | mmap   |        n/a |   6.208 µs  71% |   4.786 µs  71% |   4.572 µs  61%
   Find duration *LA                      | master |        n/a |   4.354 µs      |   5.743 µs      |   6.603 µs     
                                          | mmap   |        n/a |   3.743 µs  86% |   5.109 µs  89% |   5.379 µs  81%
   Mem duration *LA                       | master |        n/a |   2.405 µs      |   2.721 µs      |   2.773 µs     
                                          | mmap   |        n/a |   2.407 µs 100% |   2.612 µs  96% |   2.424 µs  87%
   Mem_tree duration *LA                  | master |        n/a |   1.023 µs      |   1.214 µs      |   1.476 µs     
                                          | mmap   |        n/a |   0.957 µs  94% |   1.330 µs 110% |   1.454 µs  99%
   Copy duration *LA                      | master |        n/a |  23.173 µs      |   6.694 µs      |   6.828 µs     
                                          | mmap   |        n/a |   7.176 µs  31% |  17.313 µs 259% |   6.759 µs  99%
   Checkout duration *LA                  | master |        n/a |   1.915 µs      |   2.381 µs      |   2.383 µs     
                                          | mmap   |        n/a |   2.015 µs 105% |   2.297 µs  96% |   2.133 µs  90%
                                          |        |            |                 |                 | 
   Disk bytes    read *C                  | master |    0.000 G |   21.951 G      |   99.728 G      |  209.435 G     
                                          | mmap   |    0.000 G |   21.949 G 100% |   99.733 G 100% |  209.446 G 100%
   Disk bytes written *C                  | master |    0.000 G |    0.675 G      |    4.595 G      |   14.036 G     
                                          | mmap   |    0.000 G |    0.673 G 100% |    4.593 G 100% |   14.036 G 100%
   Disk bytes    both *C                  | master |    0.000 G |   22.626 G      |  104.323 G      |  223.472 G     
                                          | mmap   |    0.000 G |   22.622 G 100% |  104.326 G 100% |  223.483 G 100%
   Disk bytes read    per block *LA       | master |        n/a |  1_287_586      |  2_651_095      |  3_546_737     
                                          | mmap   |        n/a |  1_288_462 100% |  2_651_989 100% |  3_547_874 100%
   Disk bytes written per block *LA       | master |        n/a |     32_079      |    111_458      |    366_453     
                                          | mmap   |        n/a |     33_681 105% |    112_433 101% |    368_862 101%
   Disk bytes both    per block *LA       | master |        n/a |  1_319_665      |  2_762_554      |  3_913_190     
                                          | mmap   |        n/a |  1_322_142 100% |  2_764_422 100% |  3_916_736 100%
   Disk bytes read    per sec *LA *N      | master |        n/a |  179.794 M      |  236.947 M      |  234.831 M     
                                          | mmap   |        n/a |  211.456 M 118% |  277.771 M 117% |  278.128 M 118%
   Disk bytes written per sec *LA *N      | master |        n/a |    4.479 M      |    9.962 M      |   24.263 M     
                                          | mmap   |        n/a |    5.527 M 123% |   11.776 M 118% |   28.916 M 119%
   Disk bytes both    per sec *LA *N      | master |        n/a |  184.273 M      |  246.908 M      |  259.094 M     
                                          | mmap   |        n/a |  216.983 M 118% |  289.548 M 117% |  307.045 M 119%
                                          |        |            |                 |                 | 
   Disk read  count *C                    | master |    0.000 M |   10.568 M      |   42.653 M      |   83.871 M     
                                          | mmap   |    0.000 M |   10.568 M 100% |   42.653 M 100% |   83.871 M 100%
   Disk write count *C                    | master |          5 |    162_103      |    311_935      |    455_621     
                                          | mmap   |          5 |    162_099 100% |    311_933 100% |    455_621 100%
   Disk both  count *C                    | master |    0.000 M |   10.730 M      |   42.965 M      |   84.327 M     
                                          | mmap   |    0.000 M |   10.730 M 100% |   42.965 M 100% |   84.327 M 100%
   Disk read  count per block *LA         | master |        n/a |    637.080      |   1124.109      |   1426.089     
                                          | mmap   |        n/a |    637.081 100% |   1124.111 100% |   1426.091 100%
   Disk write count per block *LA         | master |        n/a |      4.514      |      4.352      |      4.242     
                                          | mmap   |        n/a |      4.517 100% |      4.353 100% |      4.244 100%
   Disk both  count per block *LA         | master |        n/a |    641.594      |   1128.461      |   1430.331     
                                          | mmap   |        n/a |    641.598 100% |   1128.464 100% |   1430.335 100%
   Disk read  count per sec *LA *N        | master |        n/a |     88_960      |    100_469      |     94_422     
                                          | mmap   |        n/a |    104_554 118% |    117_740 117% |    111_796 118%
   Disk write count per sec *LA *N        | master |        n/a |        630      |        389      |        281     
                                          | mmap   |        n/a |        741 118% |        456 117% |        333 118%
   Disk both  count per sec *LA *N        | master |        n/a |     89_590      |    100_858      |     94_703     
                                          | mmap   |        n/a |    105_296 118% |    118_196 117% |    112_128 118%
                                          |        |            |                 |                 | 
   pack.finds per block *LA               | master |        n/a |    553.313      |    789.198      |    977.697     
                                          | mmap   |        n/a |    553.313 100% |    789.198 100% |    977.697 100%
   pack.cache_misses per block *LA        | master |        n/a |     47.450      |     59.519      |     69.168     
                                          | mmap   |        n/a |     47.450 100% |     59.519 100% |     69.168 100%
   pack.appended_hashes per block *LA     | master |        n/a |  0.074_490      |  0.032_069      |  0.040_356     
                                          | mmap   |        n/a |  0.074_490 100% |  0.032_069 100% |  0.040_356 100%
   pack.appended_offsets per block *LA    | master |        n/a |    510.293      |    908.002      |   1179.177     
                                          | mmap   |        n/a |    510.293 100% |    908.002 100% |   1179.177 100%
                                          |        |            |                 |                 | 
   tree.contents_hash per block *LA       | master |        n/a |     36.548      |     55.671      |     65.147     
                                          | mmap   |        n/a |     36.548 100% |     55.671 100% |     65.147 100%
   tree.contents_find per block *LA       | master |        n/a |    119.491      |    149.254      |    165.504     
                                          | mmap   |        n/a |    119.491 100% |    149.254 100% |    165.504 100%
   tree.contents_add per block *LA        | master |        n/a |     34.110      |     49.757      |     58.392     
                                          | mmap   |        n/a |     34.110 100% |     49.757 100% |     58.392 100%
   tree.node_hash per block *LA           | master |        n/a |    101.886      |    152.333      |    179.619     
                                          | mmap   |        n/a |    101.886 100% |    152.333 100% |    179.619 100%
   tree.node_mem per block *LA            | master |        n/a |    101.111      |    151.813      |    179.152     
                                          | mmap   |        n/a |    101.111 100% |    151.813 100% |    179.152 100%
   tree.node_add per block *LA            | master |        n/a |    100.309      |    149.101      |    176.012     
                                          | mmap   |        n/a |    100.309 100% |    149.101 100% |    176.012 100%
   tree.node_find per block *LA           | master |        n/a |    202.930      |    247.157      |    273.691     
                                          | mmap   |        n/a |    202.930 100% |    247.157 100% |    273.691 100%
   tree.node_val_v per block *LA          | master |        n/a |  3.410_123      |  1.834_733      |  1.704_790     
                                          | mmap   |        n/a |  3.410_123 100% |  1.834_733 100% |  1.704_790 100%
   tree.node_val_find per block *LA       | master |        n/a |          0      |          0      |          0     
                                          | mmap   |        n/a |          0      |          0      |          0     
   tree.node_val_list per block *LA       | master |        n/a |  1.935_643      |  1.434_413      |  1.473_389     
                                          | mmap   |        n/a |  1.935_643 100% |  1.434_413 100% |  1.473_389 100%
                                          |        |            |                 |                 | 
   index.nb_merge *C                      | master |          0 |          5      |         17      |         32     
                                          | mmap   |          0 |          5 100% |         17 100% |         32 100%
   index.cumu_data_bytes *C               | master |    0.000 G |    0.226 G      |    3.069 G      |   11.194 G     
                                          | mmap   |    0.000 G |  163.840 G 726x |  655.360 G 214x | 1269.760 G 113x
   index.cumu_data_bytes per block *LA    | master |        n/a |    0.012 M      |    0.076 M      |    0.325 M     
                                          | mmap   |        n/a |    5.658 M 460x |    8.824 M 116x |   19.261 M  59x
                                          |        |            |                 |                 | 
   gc.minor_words allocated *C            | master |    0.001 G |   34.135 G      |   96.490 G      |  178.194 G     
                                          | mmap   |    0.001 G |   34.068 G 100% |   96.232 G 100% |  177.688 G 100%
   gc.minor_words allocated per block *LA | master |        n/a |  1_376_777      |  2_070_051      |  2_786_435     
                                          | mmap   |        n/a |  1_374_072 100% |  2_063_677 100% |  2_778_351 100%
   gc.promoted_words *C                   | master |    0.218 M | 1655.227 M      | 4517.364 M      | 8042.097 M     
                                          | mmap   |    0.218 M | 1652.756 M 100% | 4514.341 M 100% | 8037.622 M 100%
   gc.major_words allocated *C            | master |    0.644 M | 1699.697 M      | 4658.062 M      | 8311.963 M     
                                          | mmap   |    0.644 M | 1697.226 M 100% | 4655.039 M 100% | 8307.488 M 100%
   gc.major_words allocated per block *LA | master |        n/a |     69_297      |     98_471      |    121_944     
                                          | mmap   |        n/a |     69_247 100% |     98_447 100% |    121_853 100%
   gc.minor_collections *C                | master |          4 |    130_291      |    368_255      |    680_046     
                                          | mmap   |          4 |    130_039 100% |    367_269 100% |    678_114 100%
   gc.minor_collections per block *LA     | master |        n/a |      5.254      |      7.900      |     10.633     
                                          | mmap   |        n/a |      5.244 100% |      7.875 100% |     10.602 100%
   gc.major_collections *C                | master |          1 |        152      |        330      |        531     
                                          | mmap   |          1 |        152 100% |        329 100% |        529 100%
   gc.major_collections per block *LA     | master |        n/a |  4.789e-03      |  6.166e-03      |  6.265e-03     
                                          | mmap   |        n/a |  3.829e-03  80% |  5.444e-03  88% |  6.595e-03 105%
   gc.compactions *C                      | master |          0 |          4      |         10      |         17     
                                          | mmap   |          0 |          3  75% |          9  90% |         16  94%
                                          |        |            |                 |                 | 
   gc.major heap bytes top *C             | master |    7.664 M | 1390.957 M      | 1465.668 M      | 1465.668 M     
                                          | mmap   |    7.664 M | 1469.563 M 106% | 1469.579 M 100% | 1690.018 M 115%
   gc.major heap bytes *LA                | master |    7.664 M |  416.625 M      |  684.450 M      | 1040.974 M     
                                          | mmap   |    7.664 M | 1111.212 M 267% |  966.271 M 141% | 1032.786 M  99%
                                          |        |            |                 |                 | 
   index_data bytes *S                    | master |    0.000 G |    0.090 G      |    0.361 G      |    0.700 G     
                                          | mmap   |    0.000 G |   40.960 G 454x |   40.960 G 113x |   40.960 G  59x
   index_data bytes per block *LA         | master |        n/a |      3_109      |      4_847      |     10_581     
                                          | mmap   |        n/a |          2 0.1% |          0 0.0% |          0 0.0%
   store_pack bytes *S                    | master |    0.000 G |    0.239 G      |    0.760 G      |    1.422 G     
                                          | mmap   |   40.960 G |   40.960 G 171x |   40.960 G  54x |   40.960 G  29x
   store_pack bytes per block *LA         | master |        n/a |     10_414      |     17_367      |     21_581     
                                          | mmap   |        n/a |          0   0% |          0   0% |          0   0%
   index_log bytes *S                     | master |    0.000 G |    0.023 G      |    0.023 G      |    0.023 G     
                                          | mmap   |   40.960 G |   40.960 G 2e3x |   40.960 G 2e3x |   40.960 G 2e3x
   index_log_async *S                     | master |    0.000 G |    0.015 G      |    0.020 G      |    0.010 G     
                                          | mmap   |    0.000 G |   40.960 G 3e3x |   40.960 G 2e3x |   40.960 G 4e3x
   store_dict bytes *S                    | master |    0.000 G |    0.002 G      |    0.002 G      |    0.002 G     
                                          | mmap   |   40.960 G |   40.960 G 2e4x |   40.960 G 2e4x |   40.960 G 2e4x
                                          |        |            |                 |                 | 
   /data/contracts/index *S               | master |        n/a |          4      |          4      |          4     
                                          | mmap   |        n/a |          4 100% |          4 100% |          4 100%
   /data/big_maps/index *S                | master |        n/a |          0      |          0      |          0     
                                          | mmap   |        n/a |          0      |          0      |          0     
   /data/rolls/index *S                   | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%
   /data/rolls/owner/current *S           | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%
   /data/commitments *S                   | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%
   /data/contracts/index/ed25519 *S       | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%
   /data/contracts/index/originated *S    | master |        n/a |        256      |        256      |        256     
                                          | mmap   |        n/a |        256 100% |        256 100% |        256 100%

   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 1250.01 blocks, half of the past is forgotten.
    *S: Size. E.g. directory entries, file bytes. No smoothing.
    *N: Very noisy.

Ngoguey42 commented 3 years ago

A quick analysis of your results:

All the metrics related to file size are messed up because it seems you are allocating 41GB for each files at the beginning.

The maximum size reached by the major heap is 1796.334 M instead of 1355.502 M, but this might just be noise because the average size of the major heap is similar between the two setups.

Even if my way of calculating the CPU usage is a bit broken, it seems that the CPU usage of nmap is better (100% vs 96% on master).

The total wall time is better with nmap (13min49s vs 15min52s on master), and most of that time seem to be gained during Irmin's commits, i.e. the RW phase:

On master, commits last 7.072 ms on average (5.942 ms (84%) with nmap)
On master, buildup last 2.458 ms on average (2.358 ms (96%) with nmap). The "buildup" being everything that happens between 2 commits.

tomjridge commented 3 years ago

NOTE: to make mmap more usable, we need to avoid the appearance of frightening 40GB files (which are largely 0 bytes so likely don't actually consume disk space, but still...). So, we need to remap the mmap as the file grows rather than mmap'ing the whole file to max size upfront.

Also, 40GB is apparently the max size supported by the current OCaml runtime (although perhaps Bigarray provides larger?) and we certainly need to support larger than this.

tomjridge commented 3 years ago

Some benchmark comparisons:

index+master, 50M operations, replayed in 5m32s

index+mmap, 50M operations, replayed in 4m55s

irmin+master, 100k commits, replayed in 16m15s

irmin+mmap, 100k commits, replayed in 14m17s

irmin+hashtbl, 100k commits, replayed in 11m03s (presumably near the best possible?)

(These figures are for one run, but repeated runs show similar figures.)

Caveat: Not clear that the data is being synced properly with msync.

tomjridge commented 3 years ago

(Craig: you talked about codecs writing directly to the mmap buffer rather than going via intermediates; yes, this would likely also improve performance.)

tomjridge commented 3 years ago

Some comments about mmap: https://docs.google.com/document/d/e/2PACX-1vSSae13RwwIlIcP8Dxdwnv7tCaNcc3k0hzFLa1kRmcIsDYtqVbyMKMoHNJADi9tN7WKnsDXANHqhRZ4/pub

tomjridge commented 3 years ago

I added msync: https://github.com/tomjridge/index/tree/mmap-wip

Another benchmark: index+mmap+msync, 50M operations, replayed in 5m13s. So msync indeed makes things significantly slower.

I guess one of the things I worry about is that sync operations (fsync, msync) are expensive, and we don't seem to have a good handle on when we use them. If we can avoid using them, performance will likely improve!

samoht commented 2 years ago

I guess one of the things I worry about is that sync operations (fsync, msync) are expensive, and we don't seem to have a good handle on when we use them. If we can avoid using them, performance will likely improve!

You are right, let's not do this. Others have pointed out it's a bad idea too: http://cidrdb.org/cidr2022/papers/p13-crotty.pdf

mirage / index

Investigate using mmap instead of preads and pwrites #350