fix: Wrong metrics in the report of the WS performance tests

victor-yanev commented 2 weeks ago

Description:

Problem

The current report of the k6 performance tests for the WS-server is currently misleading:

the scenario duration is not correctly captured since the actual duration should be taken from the moment that the JSON-RPC request is sent to the WS server until the moment a message with the JSON-RPC response is received from the WS server. Instead, the scenarioDurationGauge is currently only tracking the duration of the request which establishes connection with the WS server and not the actual JSON-RPC request.

Solution

Refactor the current tests to capture valid scenario duration metrics in the report (through the scenarioDurationGauge)

Related issue(s):

Fixes #3167

Notes for reviewer:

Results after running the WS performance tests against testnet:

     checks.......................................................................: 100.00% ✓ 4318      ✗ 0     
     ✓ { scenario:eth_chainId }...................................................: 100.00% ✓ 1656      ✗ 0     
     ✓ { scenario:eth_subscribe_logs }............................................: 100.00% ✓ 519       ✗ 0     
     ✓ { scenario:eth_subscribe_newHeads }........................................: 100.00% ✓ 1141      ✗ 0     
     ✓ { scenario:eth_subscribe_newPendingTransactions }..........................: 100.00% ✓ 1002      ✗ 0     
     data_received................................................................: 16 MB   43 kB/s
     data_sent....................................................................: 3.4 MB  8.9 kB/s
     http_req_blocked.............................................................: avg=28.05ms  min=14.37ms  med=18.95ms max=59.93ms  p(90)=48.59ms  p(95)=54.26ms 
     http_req_connecting..........................................................: avg=6.92ms   min=5.36ms   med=7.28ms  max=7.78ms   p(90)=7.7ms    p(95)=7.74ms  
     http_req_duration............................................................: avg=78.83ms  min=61.15ms  med=67.91ms max=118.36ms p(90)=104.64ms p(95)=111.5ms 
       { expected_response:true }.................................................: avg=78.83ms  min=61.15ms  med=67.91ms max=118.36ms p(90)=104.64ms p(95)=111.5ms 
     ✓ { scenario:eth_chainId,expected_response:true }............................: avg=0s       min=0s       med=0s      max=0s       p(90)=0s       p(95)=0s      
     ✓ { scenario:eth_subscribe_logs,expected_response:true }.....................: avg=0s       min=0s       med=0s      max=0s       p(90)=0s       p(95)=0s      
     ✓ { scenario:eth_subscribe_newHeads,expected_response:true }.................: avg=0s       min=0s       med=0s      max=0s       p(90)=0s       p(95)=0s      
     ✓ { scenario:eth_subscribe_newPendingTransactions,expected_response:true }...: avg=0s       min=0s       med=0s      max=0s       p(90)=0s       p(95)=0s      
     http_req_failed..............................................................: 0.00%   ✓ 0         ✗ 4     
     http_req_receiving...........................................................: avg=151.75µs min=104µs    med=128µs   max=247µs    p(90)=213.7µs  p(95)=230.34µs
     http_req_sending.............................................................: avg=97µs     min=57µs     med=91.5µs  max=148µs    p(90)=136.9µs  p(95)=142.44µs
     http_req_tls_handshaking.....................................................: avg=10.47ms  min=7.9ms    med=9.49ms  max=14.98ms  p(90)=13.5ms   p(95)=14.24ms 
     http_req_waiting.............................................................: avg=78.58ms  min=60.9ms   med=67.63ms max=118.17ms p(90)=104.46ms p(95)=111.31ms
     http_reqs....................................................................: 4       0.010594/s
     ✗ { scenario:eth_chainId }...................................................: 0       0/s
     ✗ { scenario:eth_subscribe_logs }............................................: 0       0/s
     ✗ { scenario:eth_subscribe_newHeads }........................................: 0       0/s
     ✗ { scenario:eth_subscribe_newPendingTransactions }..........................: 0       0/s
     iteration_duration...........................................................: avg=7.54s    min=307.56ms med=2.32s   max=35.28s   p(90)=23.58s   p(95)=27.29s  
     iterations...................................................................: 4445    11.772777/s
     scenario_duration............................................................: 166     min=142     max=4757
     ✓ { scenario:eth_chainId }...................................................: 1311    min=142     max=4757
     ✓ { scenario:eth_subscribe_logs }............................................: 297     min=144     max=3513
     ✓ { scenario:eth_subscribe_newHeads }........................................: 289     min=142     max=2205
     ✓ { scenario:eth_subscribe_newPendingTransactions }..........................: 166     min=142     max=3074
     vus..........................................................................: 9       min=9       max=100 
     vus_max......................................................................: 100     min=100     max=100 
     ws_connecting................................................................: avg=7.29s    min=163.66ms med=2.68s   max=34.77s   p(90)=23.09s   p(95)=26.82s  
     ws_msgs_received.............................................................: 4318    11.436412/s
     ws_msgs_sent.................................................................: 4352    11.526463/s
     ws_session_duration..........................................................: avg=7.55s    min=307.5ms  med=2.37s   max=35.28s   p(90)=23.58s   p(95)=27.29s  

running (6m17.6s), 000/100 VUs, 4440 complete and 241 interrupted iterations
eth_chainId                    ✓ [======================================] 100 VUs  1m30s
eth_subscribe_logs             ✓ [======================================] 100 VUs  1m30s
eth_subscribe_newHeads         ✓ [======================================] 100 VUs  1m30s
eth_subscribe_newPendingTra... ✓ [======================================] 100 VUs  1m30s

Checklist

[x] Documented (Code comments, README, etc.)
[x] Tested (unit, integration, etc.)

sonarcloud[bot] commented 2 weeks ago

Quality Gate passed

Issues
0 New issues
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarCloud

github-actions[bot] commented 2 weeks ago

Test Results

22 files - 3 270 suites - 66 35m 6s :stopwatch: - 3m 39s 605 tests - 2 595 :white_check_mark: + 3 4 :zzz: ±0 6 :x: - 5 716 runs - 142 704 :white_check_mark: - 131 4 :zzz: - 3 8 :x: - 8

For more details on these failures, see this check.

Results for commit 4767b4dd. ± Comparison against base commit d6fece1e.

This pull request removes 3 and adds 1 tests. Note that renamed tests count towards both.

``` "before all" hook in "Debug API Test Suite" ‑ RPC Server Acceptance Tests Acceptance tests @api-batch-3 RPC Server Acceptance Tests Debug API Test Suite "before all" hook in "Debug API Test Suite" "before each" hook for "should execute "eth_getStorageAt" request to get old state with passing specific block" ‑ RPC Server Acceptance Tests Acceptance tests @api-batch-2 RPC Server Acceptance Tests "before each" hook for "should execute "eth_getStorageAt" request to get old state with passing specific block" "before each" hook for "should verify the estimated and actual transaction fees for file transactions are approximately equal" ‑ RPC Server Acceptance Tests Acceptance tests @hbarlimiter HBAR Limiter Acceptance Tests HBAR Rate Limit Tests "before each" hook for "should verify the estimated and actual transaction fees for file transactions are approximately equal" ``` ``` "before all" hook in "RPC Server Acceptance Tests" ‑ RPC Server Acceptance Tests Acceptance tests @api-batch-1 RPC Server Acceptance Tests RPC Server Acceptance Tests "before all" hook in "RPC Server Acceptance Tests" ```

:recycle: This comment has been updated with latest results.

codecov[bot] commented 2 weeks ago

Codecov Report

All modified and coverable lines are covered by tests :white_check_mark:

Project coverage is 83.39%. Comparing base (d6fece1) to head (4767b4d). Report is 2 commits behind head on main.

Additional details and impacted files

```diff @@ Coverage Diff @@ ## main #3193 +/- ## ======================================= Coverage 83.39% 83.39% ======================================= Files 66 66 Lines 4283 4283 Branches 835 835 ======================================= Hits 3572 3572 Misses 471 471 Partials 240 240 ``` | [Flag](https://app.codecov.io/gh/hashgraph/hedera-json-rpc-relay/pull/3193/flags?src=pr&el=flags&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=hashgraph) | Coverage Δ | | |---|---|---| | [config-service](https://app.codecov.io/gh/hashgraph/hedera-json-rpc-relay/pull/3193/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=hashgraph) | `98.14% <ø> (ø)` | | | [relay](https://app.codecov.io/gh/hashgraph/hedera-json-rpc-relay/pull/3193/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=hashgraph) | `85.60% <ø> (ø)` | | | [server](https://app.codecov.io/gh/hashgraph/hedera-json-rpc-relay/pull/3193/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=hashgraph) | `83.52% <ø> (ø)` | | | [ws-server](https://app.codecov.io/gh/hashgraph/hedera-json-rpc-relay/pull/3193/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=hashgraph) | `36.87% <ø> (ø)` | | Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=hashgraph#carryforward-flags-in-the-pull-request-comment) to find out more.

hashgraph / hedera-json-rpc-relay