Light-client: Analyze performance in detail - Node vs Browser

Created on 13 Jan 2020  路  12Comments  路  Source: raiden-network/light-client

Description

Within the retro we have decided to analyze the performance in detail comparing browser with node performance. We also wanted to use the node profiler.

Wait until Kelsos Matrix #918 PR is merged.

The goal is to understand, what we can optimize on our own and what could to be optimized by the core team

Acceptance criteria

  • There are well described issues within our repo and within the Core/Service repo
  • We don't invest more than x hours (tbd) for this issue
  • There is a small presentation of our findings

Tasks

  • [ ] Rerun the commands for doing the analysis
  • [ ] Do some thinking about the analysis result
3 sdk 馃枼

Most helpful comment

Some new stats

Environment

Memory & CPU

Command:

$ clinic doctor -- node build/bundle.js --ethNode http://10.104.6.13:8545 --privateKey ~/Library/Ethereum/keystore/UTC--2020-03-05T13-07-25.368837000Z--e060e8f4e7b931d70224be3817369eba6ccb5a38 --token 0xE2b702eD684bEb02850ac604278f078A4ce8b6E6 --transfer 1 --target 0x834B9a53ab632fEaA479d8908730B2F446AC0792

Results:
https://upload.clinicjs.org/public/b1b827244a58f9cb0de59aec245f9460ee309939885e5e0ebdad0d317b20c2d6/71369.clinic-doctor.html

direct transfers (n=50)

Results in ms:

  • AVG: 2129
  • MIN: 1794
  • MAX: 2608

JSON

[
  2319,
  1899,
  2597,
  1997,
  2299,
  2092,
  1925,
  2371,
  1905,
  2107,
  1981,
  2265,
  2296,
  2155,
  2035,
  1953,
  2232,
  2012,
  2199,
  2040,
  2268,
  2219,
  2267,
  2120,
  2077,
  2237,
  1923,
  2297,
  1941,
  2496,
  2174,
  2325,
  1917,
  1934,
  2306,
  1850,
  2195,
  1934,
  2217,
  1954,
  2608,
  2011,
  1981,
  2453,
  1794,
  2400,
  1894,
  2156,
  1906,
  1933
]

one-hop transfers (n=50)

Results in ms:

  • AVG: 4764
  • MIN: 3851
  • MAX: 7310

JSON

[
  4579,
  4082,
  6352,
  4879,
  4640,
  5568,
  3982,
  4598,
  4442,
  6048,
  3994,
  4486,
  4563,
  4805,
  3898,
  4627,
  4786,
  4661,
  4269,
  4657,
  4326,
  5208,
  4978,
  4449,
  5600,
  5015,
  4763,
  4977,
  4801,
  4605,
  5427,
  3851,
  4675,
  4662,
  5039,
  7310,
  4366,
  4184,
  4759,
  4098,
  3996,
  4478,
  4505,
  4138,
  3934,
  7045,
  4377,
  5935,
  4221,
  4540
]

two-hop transfers (n=50)

Results in ms:

  • AVG: 5915
  • MIN: 5403
  • MAX: 7803

JSON

[
  6990,
  6434,
  6288,
  5558,
  5942,
  6197,
  5952,
  5891,
  5967,
  5565,
  5555,
  6174,
  5824,
  5963,
  6562,
  5715,
  5866,
  6294,
  6123,
  5744,
  5410,
  5708,
  5855,
  5513,
  5584,
  5674,
  5560,
  5403,
  6288,
  6026,
  5841,
  5702,
  5613,
  5753,
  5466,
  5780,
  5825,
  5852,
  5750,
  5535,
  6247,
  5436,
  6462,
  7803,
  6252,
  5534,
  5816,
  5517,
  6017,
  5923
]

three-hop transfers (n=50)

Results in ms:

  • AVG: 7601
  • MIN: 6723
  • MAX: 9380

All 12 comments

I have measured the node performance using clinicjs and @andrevmatos raiden-cli.

All profiles and transfer times were measured on my local deveopment machine:

  • Architecture: i386
  • OS:

    • ProductName: Mac OS X

    • ProductVersion: 10.15.2

    • BuildVersion: 19C57

  • Processor: 2,7 GHz Dual-Core Intel Core i5
  • RAM: 8 GB 1867 MHz DDR3

Memory & CPU

Command:

$ clinic doctor -- node build/index.js -k ~/Library/Ethereum/keystore/UTC--2020-01-10T10-33-56.108810000Z--5407a578471b8cfa496dc8656271eb1e81027577 --token 0x31aA9D3E2bd38d22CA3Ae9be7aae1D518fe46043 --transfer 1 --target 0x05322f1440BC28Cb2d8A14f0965af02049720dB9

Results: https://upload.clinicjs.org/public/e7642bcd217a0c97cfcf259c77d541f6514e8e148bdfcab4dccd9c622d2db1e0/26101.clinic-doctor.html

Flame chart

Command:

$ clinic flame -- node build/index.js -k ~/Library/Ethereum/keystore/UTC--2020-01-10T10-33-56.108810000Z--5407a578471b8cfa496dc8656271eb1e81027577 --token 0x31aA9D3E2bd38d22CA3Ae9be7aae1D518fe46043 --transfer 1 --target 0x05322f1440BC28Cb2d8A14f0965af02049720dB9

Results: https://upload.clinicjs.org/public/592147e6187e3f34eeee5e717defdaa7facbd37bbba1ec550fffa096b89bb3ba/24611.clinic-flame.html#selectedNode=1884&zoomedNode=&exclude=8000-0-0-f00&merged=true

Bubbleprof chart

Command:

$ clinic bubbleprof -- node build/index.js -k ~/Library/Ethereum/keystore/UTC--2020-01-10T10-33-56.108810000Z--5407a578471b8cfa496dc8656271eb1e81027577 --token 0x31aA9D3E2bd38d22CA3Ae9be7aae1D518fe46043 --transfer 1 --target 0x05322f1440BC28Cb2d8A14f0965af02049720dB9

Results: https://upload.clinicjs.org/public/c178493491ae4df6e6e6210f4707952f2956c36928b0330083d8b153e000a510/25281.clinic-bubbleprof.html

50 sequential transfers (transport01)

I also ran 50 sequential transfers using the CLI against the Raiden Python Client.
Transport Server: https://transport01.raiden.network
Transport Server Location: Toronto, Canada
My Location: Brandenburg, Germany

Results as JSON

[
    {
        "total": 32048,
        "reveal": 9178,
        "unlock": 25559
    },
    {
        "total": 10430,
        "reveal": 5252,
        "unlock": 7715
    },
    {
        "total": 8125,
        "reveal": 3179,
        "unlock": 5671
    },
    {
        "total": 7911,
        "reveal": 3103,
        "unlock": 5280
    },
    {
        "total": 8727,
        "reveal": 3522,
        "unlock": 6155
    },
    {
        "total": 7849,
        "reveal": 3142,
        "unlock": 5360
    },
    {
        "total": 8440,
        "reveal": 3866,
        "unlock": 6062
    },
    {
        "total": 7536,
        "reveal": 2155,
        "unlock": 4228
    },
    {
        "total": 7332,
        "reveal": 2350,
        "unlock": 4766
    },
    {
        "total": 8563,
        "reveal": 3044,
        "unlock": 5350
    },
    {
        "total": 7141,
        "reveal": 2799,
        "unlock": 4609
    },
    {
        "total": 8370,
        "reveal": 3292,
        "unlock": 5475
    },
    {
        "total": 7226,
        "reveal": 2269,
        "unlock": 4718
    },
    {
        "total": 8386,
        "reveal": 2239,
        "unlock": 4794
    },
    {
        "total": 6545,
        "reveal": 1997,
        "unlock": 4032
    },
    {
        "total": 8068,
        "reveal": 2501,
        "unlock": 5794
    },
    {
        "total": 7784,
        "reveal": 3164,
        "unlock": 5296
    },
    {
        "total": 8624,
        "reveal": 2986,
        "unlock": 6105
    },
    {
        "total": 8313,
        "reveal": 3618,
        "unlock": 5773
    },
    {
        "total": 8137,
        "reveal": 2863,
        "unlock": 5136
    },
    {
        "total": 8277,
        "reveal": 3223,
        "unlock": 5437
    },
    {
        "total": 8387,
        "reveal": 3165,
        "unlock": 5765
    },
    {
        "total": 6850,
        "reveal": 2378,
        "unlock": 4455
    },
    {
        "total": 7644,
        "reveal": 2672,
        "unlock": 5125
    },
    {
        "total": 6997,
        "reveal": 2634,
        "unlock": 4418
    },
    {
        "total": 7677,
        "reveal": 2725,
        "unlock": 5174
    },
    {
        "total": 7290,
        "reveal": 2659,
        "unlock": 4866
    },
    {
        "total": 8236,
        "reveal": 3910,
        "unlock": 5713
    },
    {
        "total": 8079,
        "reveal": 3082,
        "unlock": 5212
    },
    {
        "total": 7435,
        "reveal": 2724,
        "unlock": 4933
    },
    {
        "total": 8360,
        "reveal": 3263,
        "unlock": 5424
    },
    {
        "total": 7887,
        "reveal": 3199,
        "unlock": 5424
    },
    {
        "total": 8787,
        "reveal": 2704,
        "unlock": 4842
    },
    {
        "total": 8280,
        "reveal": 3094,
        "unlock": 5451
    },
    {
        "total": 8600,
        "reveal": 3128,
        "unlock": 4921
    },
    {
        "total": 8532,
        "reveal": 3635,
        "unlock": 5965
    },
    {
        "total": 8864,
        "reveal": 3132,
        "unlock": 6175
    },
    {
        "total": 7294,
        "reveal": 2424,
        "unlock": 4885
    },
    {
        "total": 7618,
        "reveal": 2700,
        "unlock": 5068
    },
    {
        "total": 8369,
        "reveal": 3389,
        "unlock": 5652
    },
    {
        "total": 9058,
        "reveal": 3647,
        "unlock": 6097
    },
    {
        "total": 7880,
        "reveal": 2824,
        "unlock": 5005
    },
    {
        "total": 8294,
        "reveal": 3244,
        "unlock": 5832
    },
    {
        "total": 9146,
        "reveal": 3577,
        "unlock": 5740
    },
    {
        "total": 7353,
        "reveal": 2638,
        "unlock": 4886
    },
    {
        "total": 8339,
        "reveal": 2393,
        "unlock": 4905
    },
    {
        "total": 7541,
        "reveal": 2990,
        "unlock": 5190
    },
    {
        "total": 8402,
        "reveal": 2977,
        "unlock": 5101
    },
    {
        "total": 7802,
        "reveal": 3077,
        "unlock": 5288
    },
    {
        "total": 7809,
        "reveal": 2230,
        "unlock": 5253
    }
]

50 sequential transfers (transport04)

Same setup, just different transport server
Transport Server: https://transport04.raiden.network
Transport Server Location: Amsterdam, Netherlands
My Location: Brandenburg, Germany

Results as JSON

[
    {
        "total": 31557,
        "reveal": 12170,
        "unlock": 25630
    },
    {
        "total": 23284,
        "reveal": 6054,
        "unlock": 11553
    },
    {
        "total": 20396,
        "reveal": 4469,
        "unlock": 14055
    },
    {
        "total": 23793,
        "reveal": 12636,
        "unlock": 18738
    },
    {
        "total": 22834,
        "reveal": 11648,
        "unlock": 16675
    },
    {
        "total": 27457,
        "reveal": 8829,
        "unlock": 15864
    },
    {
        "total": 32651,
        "reveal": 11721,
        "unlock": 17104
    },
    {
        "total": 21056,
        "reveal": 4990,
        "unlock": 11956
    },
    {
        "total": 28244,
        "reveal": 10193,
        "unlock": 16977
    },
    {
        "total": 23409,
        "reveal": 6324,
        "unlock": 16018
    },
    {
        "total": 30645,
        "reveal": 10513,
        "unlock": 21121
    },
    {
        "total": 26017,
        "reveal": 6926,
        "unlock": 17396
    },
    {
        "total": 20040,
        "reveal": 5822,
        "unlock": 12352
    },
    {
        "total": 23888,
        "reveal": 7197,
        "unlock": 12989
    },
    {
        "total": 17977,
        "reveal": 7191,
        "unlock": 11051
    },
    {
        "total": 28880,
        "reveal": 5869,
        "unlock": 11011
    },
    {
        "total": 25308,
        "reveal": 7545,
        "unlock": 20349
    },
    {
        "total": 20345,
        "reveal": 9550,
        "unlock": 14614
    },
    {
        "total": 26504,
        "reveal": 12630,
        "unlock": 16402
    },
    {
        "total": 27215,
        "reveal": 5187,
        "unlock": 9965
    },
    {
        "total": 22560,
        "reveal": 5372,
        "unlock": 11442
    },
    {
        "total": 9693,
        "reveal": 3515,
        "unlock": 7643
    },
    {
        "total": 19897,
        "reveal": 3176,
        "unlock": 11676
    },
    {
        "total": 35491,
        "reveal": 9806,
        "unlock": 21547
    },
    {
        "total": 20448,
        "reveal": 5809,
        "unlock": 12239
    },
    {
        "total": 23723,
        "reveal": 8161,
        "unlock": 14326
    },
    {
        "total": 22534,
        "reveal": 6335,
        "unlock": 12672
    },
    {
        "total": 17071,
        "reveal": 6313,
        "unlock": 9220
    },
    {
        "total": 22669,
        "reveal": 6038,
        "unlock": 13407
    },
    {
        "total": 36229,
        "reveal": 6696,
        "unlock": 30986
    },
    {
        "total": 42132,
        "reveal": 13946,
        "unlock": 24356
    },
    {
        "total": 36469,
        "reveal": 11623,
        "unlock": 31438
    },
    {
        "total": 13261,
        "reveal": 8495,
        "unlock": 10138
    },
    {
        "total": 8356,
        "reveal": 4517,
        "unlock": 6407
    },
    {
        "total": 5516,
        "reveal": 2078,
        "unlock": 3338
    },
    {
        "total": 8446,
        "reveal": 3330,
        "unlock": 6616
    },
    {
        "total": 6615,
        "reveal": 1370,
        "unlock": 3348
    },
    {
        "total": 5208,
        "reveal": 1586,
        "unlock": 3046
    },
    {
        "total": 7208,
        "reveal": 1750,
        "unlock": 3203
    },
    {
        "total": 5848,
        "reveal": 1175,
        "unlock": 3225
    },
    {
        "total": 7150,
        "reveal": 1269,
        "unlock": 3145
    },
    {
        "total": 6035,
        "reveal": 2134,
        "unlock": 3439
    },
    {
        "total": 7065,
        "reveal": 1346,
        "unlock": 3296
    },
    {
        "total": 5105,
        "reveal": 1511,
        "unlock": 3169
    },
    {
        "total": 6979,
        "reveal": 1288,
        "unlock": 4984
    },
    {
        "total": 6990,
        "reveal": 2372,
        "unlock": 3639
    },
    {
        "total": 7602,
        "reveal": 1606,
        "unlock": 5111
    },
    {
        "total": 11018,
        "reveal": 1578,
        "unlock": 3902
    },
    {
        "total": 35695,
        "reveal": 8100,
        "unlock": 27713
    },
    {
        "total": 5669,
        "reveal": 1826,
        "unlock": 3687
    }
]

@nephix Great, thanks :)

The Results in JSON describes the time in ms, right?

@eorituz This might be also interesting for you :)

Yes it's in ms and both clients (Raiden core client and raiden js CLI) used the same transport server. After talking to @andrevmatos we mostly concluded that the matrix sdk and/or the servers are the bottleneck

I guess the overwhelming question now is "why the fuck are the transfers 2x slower using a matrix server that is geographically closer to the raiden clients".
@christianbrb is that worth its own issue?

I am under the impression that lately everyone uses the transport04 server, so it might have been due to load, can we compare the load based on the monitoring data?

@ulope mentioned, that metrics are activated on the transport servers. @ulope Could you check transport04 ?

@christianbrb Yes that is why I mentioned, but do we have historical data from the period when the benchmark happened?

Some new stats

Environment

Memory & CPU

Command:

$ clinic doctor -- node build/bundle.js --ethNode http://10.104.6.13:8545 --privateKey ~/Library/Ethereum/keystore/UTC--2020-03-05T13-07-25.368837000Z--e060e8f4e7b931d70224be3817369eba6ccb5a38 --token 0xE2b702eD684bEb02850ac604278f078A4ce8b6E6 --transfer 1 --target 0x834B9a53ab632fEaA479d8908730B2F446AC0792

Results:
https://upload.clinicjs.org/public/b1b827244a58f9cb0de59aec245f9460ee309939885e5e0ebdad0d317b20c2d6/71369.clinic-doctor.html

direct transfers (n=50)

Results in ms:

  • AVG: 2129
  • MIN: 1794
  • MAX: 2608

JSON

[
  2319,
  1899,
  2597,
  1997,
  2299,
  2092,
  1925,
  2371,
  1905,
  2107,
  1981,
  2265,
  2296,
  2155,
  2035,
  1953,
  2232,
  2012,
  2199,
  2040,
  2268,
  2219,
  2267,
  2120,
  2077,
  2237,
  1923,
  2297,
  1941,
  2496,
  2174,
  2325,
  1917,
  1934,
  2306,
  1850,
  2195,
  1934,
  2217,
  1954,
  2608,
  2011,
  1981,
  2453,
  1794,
  2400,
  1894,
  2156,
  1906,
  1933
]

one-hop transfers (n=50)

Results in ms:

  • AVG: 4764
  • MIN: 3851
  • MAX: 7310

JSON

[
  4579,
  4082,
  6352,
  4879,
  4640,
  5568,
  3982,
  4598,
  4442,
  6048,
  3994,
  4486,
  4563,
  4805,
  3898,
  4627,
  4786,
  4661,
  4269,
  4657,
  4326,
  5208,
  4978,
  4449,
  5600,
  5015,
  4763,
  4977,
  4801,
  4605,
  5427,
  3851,
  4675,
  4662,
  5039,
  7310,
  4366,
  4184,
  4759,
  4098,
  3996,
  4478,
  4505,
  4138,
  3934,
  7045,
  4377,
  5935,
  4221,
  4540
]

two-hop transfers (n=50)

Results in ms:

  • AVG: 5915
  • MIN: 5403
  • MAX: 7803

JSON

[
  6990,
  6434,
  6288,
  5558,
  5942,
  6197,
  5952,
  5891,
  5967,
  5565,
  5555,
  6174,
  5824,
  5963,
  6562,
  5715,
  5866,
  6294,
  6123,
  5744,
  5410,
  5708,
  5855,
  5513,
  5584,
  5674,
  5560,
  5403,
  6288,
  6026,
  5841,
  5702,
  5613,
  5753,
  5466,
  5780,
  5825,
  5852,
  5750,
  5535,
  6247,
  5436,
  6462,
  7803,
  6252,
  5534,
  5816,
  5517,
  6017,
  5923
]

three-hop transfers (n=50)

Results in ms:

  • AVG: 7601
  • MIN: 6723
  • MAX: 9380

Transfer times on raspberry pi... @eorituz

Direct transfers (n=50)

  • AVG: 5982
  • MIN: 4258
  • MAX: 12123

JSON

[
  6016,
  5060,
  5140,
  4277,
  4571,
  4815,
  4921,
  5107,
  12123,
  9680,
  11985,
  5061,
  4886,
  4799,
  10482,
  10131,
  5345,
  9211,
  5068,
  6544,
  10423,
  10256,
  4981,
  5484,
  4934,
  4351,
  4317,
  5171,
  4467,
  10296,
  4650,
  5706,
  4480,
  4369,
  6131,
  4485,
  4930,
  5383,
  4905,
  4258,
  5018,
  5218,
  5356,
  5073,
  4434,
  5317,
  5577,
  4753,
  4582,
  4596
]

Mediated transfers (n=10, hop=1)

CPU/Memory: https://upload.clinicjs.org/public/947424ccd5f694af4735e26a5e4d58d2faf37fe0d6eeda94ca7045c12ecf5734/1316.clinic-doctor.html

Mediated transfers (n=50, hop=1)

  • AVG: 12164
  • MIN: 8538
  • MAX: 25174

JSON

[
  14410,
  11527,
  12396,
  13905,
  11462,
  11354,
  9726,
  11866,
  16246,
  11572,
  10533,
  9723,
  10614,
  11128,
  10427,
  12086,
  11698,
  21139,
  11164,
  10123,
  10067,
  8988,
  10908,
  9534,
  11338,
  8538,
  9933,
  13123,
  9487,
  14717,
  11600,
  9761,
  13158,
  10593,
  10695,
  19581,
  11486,
  12839,
  11218,
  9652,
  12140,
  9277,
  19437,
  10699,
  10527,
  25174,
  12507,
  12190,
  11247,
  14687
]

As the speed test on the pi is done, I'm unassigning myself and put this back to the backlog

Nano pi transfer times (via matrix)

Direct transfer (n=50)

  • AVG: 4173
  • MIN: 3419
  • MAX: 8792

Mediated transfer (n=50, hops=1)

  • AVG: 6619
  • MIN: 5721
  • MAX: 15483

Danke f眉r die M眉he!
Leider ist das zu langsam, besonders die peak zeit ist 眉bel...

Was this page helpful?
0 / 5 - 0 ratings

Related issues

kelsos picture kelsos  路  6Comments

christianbrb picture christianbrb  路  5Comments

MrCleanerPickerUpper picture MrCleanerPickerUpper  路  6Comments

christianbrb picture christianbrb  路  5Comments

christianbrb picture christianbrb  路  3Comments