Profiling node performance

Development
6

I wanted a way to profile a network of vaults, so perf as in the original post wasn’t going to cut it.

I added log messages at the start and end of every function in the vault code. Parsing the timestamps of the messages gives an indication of the time consumed by each method.

Here’s the environment for the first experiment:

Vault 10.5.0
Group Size of 3
Quorum Size of 2
7 x Pine64
Quadcore
Debian aarch64
2GB RAM
Gigabit ethernet
64GB Kingston MicroSD
28 vaults total

Launcher 0.7.1
Ubuntu 16.04 x64

Demo App 0.5.1
Ubuntu 16.04 x64

10:52:45 - start file upload

Size: 686.8 MB
Name: ubuntu-16.04-server-amd64.iso
SHA256: b8b172cbdf04f5ff8adc8c2c1b4007ccf66f00fc6a324a6da6eba67de71746f6

11:52:00 - end file upload

and the results:


                                                 Method    Duration (s)  RunCount
                                       vault.rs:115:run  2552.60870983        33
                                 chunk_store.rs:103:put  1510.47436018      2046
          data_manager.rs:578:send_gets_for_needed_data  1173.55571553     20937
                maid_manager.rs:285:forward_put_request  967.770070733      1992
                             vault.rs:175:process_event  205.934719917     14799
                         data_manager.rs:340:handle_put  176.054347865      1992
                       maid_manager.rs:239:send_refresh  111.245907806      1992
                 maid_manager.rs:117:handle_put_success   80.609155668      1992
                          vault.rs:83:vault_with_config   38.724921621        61
                     maid_manager.rs:180:handle_refresh   33.742462612      1992
                       data_manager.rs:759:send_refresh   33.543854022      2046
                        data_manager.rs:200:needed_data   31.490390826     20904
          maid_manager.rs:251:handle_put_immutable_data   14.932050575      1965
                               vault.rs:264:on_response   12.512659774      1992
                                 chunk_store.rs:150:has    8.159158608      3957
                                vault.rs:205:on_request    7.215548172     12303
                          maid_manager.rs:94:handle_put    3.472981887      1992
                           chunk_store.rs:219:file_path    3.271853595      6255
                           chunk_store.rs:210:do_delete    2.397543187      2046
                                chunk_store.rs:227:drop    2.119100287        33
... only top 20 shown

The surprising part to me is chunk_store.rs:103:put consumed the most time, ie writing the chunk to the microsd.

2046 chunks at 1 MB/chunk is almost exactly 3 x 686 (very satisfying!)

But the rate of 2046 MB / 1510 s = 1.35 MB/s is extremely low.

The next question I want to explore is synchronous vs asynchronous characteristics on the network, ie where are the blockages that prevent full consumption of network / cpu / io?

Any comments, questions or grievances are most welcome.

8 Likes