search

duality-labs / hapi-indexer

A Node.js based indexer for the Duality Cosmos chain
1 stars 0 forks source link

feat: identify bottlenecks of transaction imports #33

Closed dib542 closed 10 months ago

dib542 commented 11 months ago

this PR adds much more detailed timings in the logs of the indexer to details how fast each part of the transaction syncing takes the most time.

Previously

A single line was used per import request and processing

1698692500208,info: import progress:   0.1% (1 items) (fetching: 264,276ms, parsing:  28ms, processing: 3,729ms per item)

Now

A breakdown of the timing is included, and the "fetching" category is broken down into "fetching" and "back-off" to distinguish between active fetching and waiting in between fetches due to the back-off algorithm.

Here is a typical breakdown of the syncing of a single transaction after many requests to a cloud node have failed.

1698692500208,info: import progress:   0.1% (1 items) (fetching: 93,201ms, parsing:  28ms, processing: 3,729ms per item)
1698692500213,info: timing:
1698692500213,back-off                                                 : 171074.52ms (called   18 times:   9504.140ms per call)
1698692500213,back-off:txs                                             : 171074.52ms (called   18 times:   9504.140ms per call)
1698692500213,fetching                                                 :  93201.34ms (called   20 times:   4660.067ms per call)
1698692500213,fetching:height                                          :      3.37ms (called    1 times:      3.371ms per call)
1698692500213,fetching:height:try-000                                  :      3.37ms (called    1 times:      3.371ms per call)
1698692500213,fetching:height:try-000:last                             :      3.37ms (called    1 times:      3.371ms per call)
1698692500213,fetching:txs                                             :  93197.97ms (called   19 times:   4905.156ms per call)
1698692500213,fetching:txs:try-000                                     :  20048.28ms (called    1 times:  20048.284ms per call)
1698692500213,fetching:txs:try-001                                     :  20409.78ms (called    1 times:  20409.781ms per call)
1698692500213,fetching:txs:try-002                                     :  19101.12ms (called    1 times:  19101.122ms per call)
1698692500213,fetching:txs:try-003                                     :  30801.70ms (called    1 times:  30801.698ms per call)
1698692500213,fetching:txs:try-004                                     :   2069.35ms (called    1 times:   2069.353ms per call)
1698692500213,fetching:txs:try-005                                     :      3.42ms (called    1 times:      3.421ms per call)
1698692500213,fetching:txs:try-006                                     :      5.07ms (called    1 times:      5.070ms per call)
1698692500213,fetching:txs:try-007                                     :      4.96ms (called    1 times:      4.965ms per call)
1698692500213,fetching:txs:try-008                                     :      7.08ms (called    1 times:      7.078ms per call)
1698692500213,fetching:txs:try-009                                     :      4.55ms (called    1 times:      4.554ms per call)
1698692500213,fetching:txs:try-010                                     :      2.84ms (called    1 times:      2.844ms per call)
1698692500213,fetching:txs:try-011                                     :      4.14ms (called    1 times:      4.142ms per call)
1698692500213,fetching:txs:try-012                                     :      3.10ms (called    1 times:      3.099ms per call)
1698692500213,fetching:txs:try-013                                     :      4.79ms (called    1 times:      4.792ms per call)
1698692500213,fetching:txs:try-014                                     :      5.66ms (called    1 times:      5.663ms per call)
1698692500213,fetching:txs:try-015                                     :      3.82ms (called    1 times:      3.819ms per call)
1698692500213,fetching:txs:try-016                                     :      6.97ms (called    1 times:      6.965ms per call)
1698692500213,fetching:txs:try-017                                     :      3.93ms (called    1 times:      3.935ms per call)
1698692500213,fetching:txs:try-018                                     :    707.39ms (called    1 times:    707.389ms per call)
1698692500213,fetching:txs:try-018:last                                :    707.39ms (called    1 times:    707.389ms per call)
1698692500213,parsing                                                  :     28.05ms (called    2 times:     14.023ms per call)
1698692500213,parsing:height                                           :      0.46ms (called    1 times:      0.463ms per call)
1698692500213,parsing:txs                                              :     27.58ms (called    1 times:     27.583ms per call)
1698692500213,parsing:txs:size-1                                       :     27.58ms (called    1 times:     27.583ms per call)
1698692500213,processing                                               :   3729.42ms (called 5408 times:      0.690ms per call)
1698692500213,processing:txs                                           :   3729.42ms (called 5408 times:      0.690ms per call)
1698692500213,processing:txs:block                                     :      1.67ms (called    1 times:      1.670ms per call)
1698692500213,processing:txs:derived.tick_state                        :    453.46ms (called  400 times:      1.134ms per call)
1698692500213,processing:txs:derived.tick_state:get                    :    234.72ms (called  200 times:      1.174ms per call)
1698692500213,processing:txs:derived.tick_state:get:tick_state         :    234.72ms (called  200 times:      1.174ms per call)
1698692500213,processing:txs:derived.tick_state:set                    :    218.74ms (called  200 times:      1.094ms per call)
1698692500213,processing:txs:derived.tick_state:set:tick_state         :    218.74ms (called  200 times:      1.094ms per call)
1698692500213,processing:txs:derived.tx_price_data                     :    777.80ms (called  407 times:      1.911ms per call)
1698692500213,processing:txs:derived.tx_price_data:get                 :    772.11ms (called  400 times:      1.930ms per call)
1698692500213,processing:txs:derived.tx_price_data:get:tick_state      :    427.07ms (called  200 times:      2.135ms per call)
1698692500213,processing:txs:derived.tx_price_data:get:tx_price_data   :    345.04ms (called  200 times:      1.725ms per call)
1698692500213,processing:txs:derived.tx_price_data:set                 :      5.69ms (called    7 times:      0.813ms per call)
1698692500213,processing:txs:derived.tx_price_data:set:tx_price_data   :      5.69ms (called    7 times:      0.813ms per call)
1698692500213,processing:txs:derived.tx_volume_data                    :    988.87ms (called  550 times:      1.798ms per call)
1698692500213,processing:txs:derived.tx_volume_data:get                :    780.23ms (called  400 times:      1.951ms per call)
1698692500213,processing:txs:derived.tx_volume_data:get:tick_state     :    381.35ms (called  200 times:      1.907ms per call)
1698692500213,processing:txs:derived.tx_volume_data:get:tx_volume_data :    398.89ms (called  200 times:      1.994ms per call)
1698692500213,processing:txs:derived.tx_volume_data:set                :    208.64ms (called  150 times:      1.391ms per call)
1698692500213,processing:txs:derived.tx_volume_data:set:tx_volume_data :    208.64ms (called  150 times:      1.391ms per call)
1698692500213,processing:txs:dex.pairs                                 :    268.87ms (called  912 times:      0.295ms per call)
1698692500213,processing:txs:dex.tokens                                :    370.92ms (called  912 times:      0.407ms per call)
1698692500213,processing:txs:event.Deposit                             :    109.06ms (called  100 times:      1.091ms per call)
1698692500213,processing:txs:event.TickUpdate                          :    260.34ms (called  300 times:      0.868ms per call)
1698692500213,processing:txs:event.TickUpdate:get                      :    215.45ms (called  200 times:      1.077ms per call)
1698692500213,processing:txs:event.TickUpdate:get:event.TickUpdate     :    215.45ms (called  200 times:      1.077ms per call)
1698692500213,processing:txs:event.TickUpdate:set                      :     44.89ms (called  100 times:      0.449ms per call)
1698692500213,processing:txs:event.TickUpdate:set:event.TickUpdate     :     44.89ms (called  100 times:      0.449ms per call)
1698692500213,processing:txs:tx                                        :      1.57ms (called    1 times:      1.568ms per call)
1698692500213,processing:txs:tx_msg                                    :     26.33ms (called  912 times:      0.029ms per call)
1698692500213,processing:txs:tx_result.events                          :   1249.93ms (called  912 times:      1.371ms per call)
dib542 commented 8 months ago

Here is an example of the import speeds after several thousand transactions have been imported:

[start] info: import progress:  82.7% (3,600 items) (fetching:  4,614ms, parsing: 381ms, processing: 21,250ms per item)
--
[start] info: timing:
[start] fetching                                                 :    4614.45ms (called    101 times:      45.688ms per call)
[start] fetching:height                                          :     259.52ms (called    100 times:       2.595ms per call)
[start] fetching:height:try-000                                  :     259.52ms (called    100 times:       2.595ms per call)
[start] fetching:height:try-000:last                             :     259.52ms (called    100 times:       2.595ms per call)
[start] fetching:txs                                             :    4354.94ms (called      1 times:    4354.936ms per call)
[start] fetching:txs:try-000                                     :    4354.94ms (called      1 times:    4354.936ms per call)
[start] fetching:txs:try-000:last                                :    4354.94ms (called      1 times:    4354.936ms per call)
[start] parsing                                                  :     381.10ms (called    101 times:       3.773ms per call)
[start] parsing:height                                           :      15.68ms (called    100 times:       0.157ms per call)
[start] parsing:txs                                              :     365.42ms (called      1 times:     365.418ms per call)
[start] parsing:txs:size-100                                     :     365.42ms (called      1 times:     365.418ms per call)
[start] processing                                               : 2125047.65ms (called 399645 times:       5.317ms per call)
[start] processing:txs                                           : 2125047.65ms (called 399645 times:       5.317ms per call)
[start] processing:txs:block                                     :      41.62ms (called    100 times:       0.416ms per call)
[start] processing:txs:derived.tick_state                        :   10654.45ms (called  58665 times:       0.182ms per call)
[start] processing:txs:derived.tick_state:get                    :    6313.35ms (called  39064 times:       0.162ms per call)
[start] processing:txs:derived.tick_state:get:tick_state         :    6313.35ms (called  39064 times:       0.162ms per call)
[start] processing:txs:derived.tick_state:set                    :    4341.10ms (called  19601 times:       0.221ms per call)
[start] processing:txs:derived.tick_state:set:tick_state         :    4341.10ms (called  19601 times:       0.221ms per call)
[start] processing:txs:derived.tx_price_data                     : 2073475.75ms (called  58614 times:      35.375ms per call)
[start] processing:txs:derived.tx_price_data:get                 : 2060363.50ms (called  39202 times:      52.558ms per call)
[start] processing:txs:derived.tx_price_data:get:tick_state      : 2055715.09ms (called  19601 times:     104.878ms per call)
[start] processing:txs:derived.tx_price_data:get:tx_price_data   :    4648.41ms (called  19601 times:       0.237ms per call)
[start] processing:txs:derived.tx_price_data:set                 :   13112.25ms (called  19412 times:       0.675ms per call)
[start] processing:txs:derived.tx_price_data:set:tx_price_data   :   13112.25ms (called  19412 times:       0.675ms per call)
[start] processing:txs:derived.tx_volume_data                    : 2073077.26ms (called  58734 times:      35.296ms per call)
[start] processing:txs:derived.tx_volume_data:get                : 2067400.52ms (called  39202 times:      52.737ms per call)
[start] processing:txs:derived.tx_volume_data:get:tick_state     : 2061672.99ms (called  19601 times:     105.182ms per call)
[start] processing:txs:derived.tx_volume_data:get:tx_volume_data :    5727.54ms (called  19601 times:       0.292ms per call)
[start] processing:txs:derived.tx_volume_data:set                :    5676.73ms (called  19532 times:       0.291ms per call)
[start] processing:txs:derived.tx_volume_data:set:tx_volume_data :    5676.73ms (called  19532 times:       0.291ms per call)
[start] processing:txs:dex.pairs                                 :    6640.34ms (called  41144 times:       0.161ms per call)
[start] processing:txs:dex.tokens                                :    6994.06ms (called  41144 times:       0.170ms per call)
[start] processing:txs:event.Deposit                             :      19.03ms (called     80 times:       0.238ms per call)
[start] processing:txs:event.PlaceLimitOrder                     :      10.76ms (called     40 times:       0.269ms per call)
[start] processing:txs:event.TickUpdate                          :   12126.87ms (called  58596 times:       0.207ms per call)
[start] processing:txs:event.TickUpdate:get                      :    6512.63ms (called  39064 times:       0.167ms per call)
[start] processing:txs:event.TickUpdate:get:event.TickUpdate     :    6512.63ms (called  39064 times:       0.167ms per call)
[start] processing:txs:event.TickUpdate:set                      :    5614.24ms (called  19532 times:       0.287ms per call)
[start] processing:txs:event.TickUpdate:set:event.TickUpdate     :    5614.24ms (called  19532 times:       0.287ms per call)
[start] processing:txs:event.Withdraw                            :       8.92ms (called     40 times:       0.223ms per call)
[start] processing:txs:tx                                        :      21.37ms (called    100 times:       0.214ms per call)
[start] processing:txs:tx_msg                                    :     703.46ms (called  41144 times:       0.017ms per call)
[start] processing:txs:tx_result.events                          :   15379.93ms (called  41144 times:       0.374ms per call)

The main issue appears to be the "get tick state" step of processing data for both the derived.tx_price_data and derived.tx_volume_data tables.