test: Refactor Existing k6 Tests to Measure Accurately

* Refactored existing tests to give us more accurate average readings

Signed-off-by: Atanas Atanasov <a.v.atanasov98@gmail.com>

Author: ata-nas

tools-and-tests/k6/average-load/bn-server-status.js

@@ -6,8 +6,8 @@ import {ServerStatusRequest} from "../lib/grpc.js";
 // Configure k6 VUs scheduling and iterations & thresholds
 export const options = {
     stages: [
-        { duration: '2m', target: 40 }, // traffic ramp-up from 1 to 40 users (all CNs and a shadow MN) over 5 minutes.
-        { duration: '3m', target: 100 }, // stay at 100 users for 3 minutes
+        { duration: '1m', target: 40 }, // traffic ramp-up from 1 to 40 users (all CNs and a shadow MN) over 5 minutes.
+        { duration: '1m', target: 100 }, // stay at 100 users for 3 minutes
         { duration: '1m', target: 0 }, // ramp-down to 0 users
     ],
     thresholds: { // todo make these good defaults, we need these to display tags in the result, but also to ping us if they go over

tools-and-tests/k6/package-lock.json

@@ -74,7 +74,7 @@ run_server_status_test() {
 
 run_query_validation_test() {
     run_bn
-    run_simulator 0 10
+    run_simulator 0 100
     echo "Running query validation test..."
     k6 run ./smoke/bn-query-validation.js >> "${k6_out_file}" 2>&1
     echo "Query validation test completed."

tools-and-tests/k6/run-k6-tests.sh

@@ -7,12 +7,10 @@ import {GetBlockRequest, ServerStatusRequest} from "../lib/grpc.js";
 export const options = {
     thresholds: { // todo make these good defaults, we need these to display tags in the result, but also to ping us if they go over
         'grpc_req_duration{name:block_node_server_status}': ['p(95)<300'],
-        'grpc_req_duration{name:get_first_block}': ['p(95)<300'],
-        'grpc_req_duration{name:get_last_block}': ['p(95)<300'],
+        'grpc_req_duration{name:get_block}': ['p(95)<300'],
     },
 };
 
-
 // load test configuration data
 const data = new SharedArray('BN Test Configs', function () {
     return JSON.parse(open('./../data.json')).configs;
@@ -26,7 +24,7 @@ client.load([data.protobufPath],
     'block-node/api/block_stream_subscribe_service.proto');
 
 // run test
-export default () => {
+export default async () => {
     client.connect(data.blockNodeUrl, {
         plaintext: true
     });
@@ -44,24 +42,26 @@ export default () => {
     if (firstAvailableBlock === '18446744073709551615') {
         console.log(`No blocks to fetch, exiting test.`);
     } else {
-        const getFirstBlockRequestParams = {
-            tags: {name: 'get_first_block'},
-        };
-        const firstAvailableBlockResponse = new GetBlockRequest(client).invoke(firstAvailableBlock, getFirstBlockRequestParams);
-        check(firstAvailableBlockResponse, {
-            'block fetch status is OK': (r) => r && r.status === StatusOK,
-            'fetched block number is correct': (r) => r && r.message.block.items[0].blockHeader.number === firstAvailableBlock,
-        });
-        console.log(`Fetched Block '${firstAvailableBlock}' with size '${firstAvailableBlockResponse.message.block.items.length}' items`);
-        const getLastBlockRequestParams = {
-            tags: {name: 'get_last_block'},
+        for (let i = parseInt(firstAvailableBlock); i <= parseInt(lastAvailableBlock); i++) {
+            const getBlockRequestParams = {
+                tags: {name: 'get_block'},
+            }
+            const blockResponse = new GetBlockRequest(client).invoke(i, getBlockRequestParams);
+            try {
+                check(blockResponse, {
+                    'block fetch status is OK': (r) => r && r.status
+                        === StatusOK,
+                    'fetched block number is correct': (r) => r && parseInt(
+                        r.message.block.items[0].blockHeader.number) === i,
+                });
+            } catch (e) {
+                console.log(`error fetching block: ${i}\nresponse: ${JSON.stringify(blockResponse)}`)
+            }
+            // Sleep just for a tiny bit, it seems networking with k6 is not always fast enough and we do see
+            // some errors when fetching blocks, sometimes no data is received at all.
+            await new Promise(r => setTimeout(r, 50));
         }
-        const lastAvailableBlockResponse = new GetBlockRequest(client).invoke(lastAvailableBlock, getLastBlockRequestParams);
-        check(lastAvailableBlockResponse, {
-            'block fetch status is OK': (r) => r && r.status === StatusOK,
-            'fetched block number is correct': (r) => r && r.message.block.items[0].blockHeader.number === lastAvailableBlock,
-        });
-        console.log(`Fetched Block '${lastAvailableBlock}' with size '${lastAvailableBlockResponse.message.block.items.length}' items`);
+        sleep(1)
     }
     client.close();
     sleep(1);

tools-and-tests/k6/smoke/bn-query-validation.js

@@ -2,6 +2,8 @@ import { Client, StatusOK, Stream } from 'k6/net/grpc';
 import { check, sleep } from 'k6';
 import { SharedArray } from 'k6/data';
 import {ServerStatusRequest, SubscribeBlockStreamRequest} from "../lib/grpc.js";
+import {Trend} from "k6/metrics";
+import { instance } from 'k6/execution';
 
 // setup options
 export const options = {
@@ -23,6 +25,9 @@ client.load([data.protobufPath],
     'block-node/api/block_access_service.proto',
     'block-node/api/block_stream_subscribe_service.proto');
 
+// this trend measures the reception of a full block along with its endOfBlock message
+const trend = new Trend('full_block_stream_duration', true);
+
 // run test
 export default () => {
     client.connect(data.blockNodeUrl, {
@@ -59,12 +64,27 @@ export default () => {
     const subscribeParams = {
         tags: {name: 'subscribe_block_stream'}
     }
+    const timingMap = new Map();
     const stream = new SubscribeBlockStreamRequest(client).invoke(subscribeParams);
     stream.on('data', (subscribeStreamResponse) => {
         if (subscribeStreamResponse.blockItems) {
-            console.log(`Stream Response: BlockHeader for Block ${JSON.stringify(subscribeStreamResponse.blockItems.blockItems[0].blockHeader.number)}`);
+            const receivedAt = instance.currentTestRunDuration;
+            const header = subscribeStreamResponse.blockItems.blockItems[0].blockHeader;
+            if (header) {
+                // we want to put in the map only if a header is present because a block
+                // could be sent in multiple chunks, we only care about the block received in full, starting from
+                // the first chunk (must include header) to the endOfBlock message
+                const bn = header.number;
+                timingMap.set(parseInt(bn), receivedAt);
+                console.log(`Stream Response: BlockHeader for Block ${JSON.stringify(bn)}`);
+            }
         } else if (subscribeStreamResponse.endOfBlock) {
-            console.log(`Stream Response: endOfBlock for Block ${JSON.stringify(subscribeStreamResponse.endOfBlock.blockNumber)}`);
+            const receivedAt = instance.currentTestRunDuration;
+            const bn = subscribeStreamResponse.endOfBlock.blockNumber;
+            const startedAt = timingMap.get(parseInt(bn));
+            trend.add(receivedAt - startedAt); // This should be accurate for more that millis (micros, nanos)
+            timingMap.delete(parseInt(bn));
+            console.log(`Stream Response: endOfBlock for Block ${JSON.stringify(bn)}`);
         } else {
             console.log(`Unknown Stream Response: , ${JSON.stringify(subscribeStreamResponse)}`);
         }