Execution order question

Grafana k6 OSS Support
1

Hi all,

not a problem per se but trying to get my head around an execution question.

I am reading config from a json file written by jenkins so the order is not always guaranteed.

sample json

[{"key":"duration","value":"30m"},{"key":"rampdown","value":"30s"},{"key":"rampup","value":"300s"}]

So I wrote some code to loop through the json and then display the variables to console.

sample code:

const testConfig = JSON.parse(open('./testfile.json')); 
for (const property in testConfig) {
  var key = testConfig[property].key;
  console.log("\tkey: " + key);
   switch (key) {
     case
       "duration":
       var duration = testConfig[property].value;
       break;
     case
       "rampup":
       var rampup = testConfig[property].value;
       break;
     case
       "rampdown":
       var rampdown = testConfig[property].value;
       break;
   }
}
console.log(`${rampup}, ${duration},${rampdown}`);

export default function () {

    console.log("starting...");
  
}

I’d expect to see the property displayed, then the variables then a starting message, what i get is:

 k6 run .\perf_k6_sample.js

          /\      |‾‾| /‾‾/   /‾‾/
     /\  /  \     |  |/  /   /  /
    /  \/    \    |     (   /   ‾‾\
   /          \   |  |\  \ |  (‾)  |
  / __________ \  |__| \__\ \_____/ .io

INFO[0000]      key: duration                                source=console
INFO[0000]      key: rampdown                                source=console
INFO[0000]      key: rampup                                  source=console
INFO[0000] 300s, 30m,30s                                 source=console
  execution: local
     script: .\perf_k6_sample.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

INFO[0000]      key: duration                                source=console
INFO[0000]      key: rampdown                                source=console
INFO[0000]      key: rampup                                  source=console
INFO[0000] 300s, 30m,30s                                 source=console
INFO[0000]      key: duration                                source=console
INFO[0000]      key: rampdown                                source=console
INFO[0000]      key: rampup                                  source=console
INFO[0000] 300s, 30m,30s                                 source=console
INFO[0000] starting...                                   source=console
INFO[0000]      key: duration                                source=console
INFO[0000]      key: rampdown                                source=console
INFO[0000]      key: rampup                                  source=console
INFO[0000] 300s, 30m,30s                                 source=console

running (00m00.2s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  00m00.0s/10m0s  1/1 iters, 1 per VU
INFO[0000]      key: duration                                source=console
INFO[0000]      key: rampdown                                source=console
INFO[0000]      key: rampup                                  source=console
INFO[0000] 300s, 30m,30s                                 source=console

     data_received........: 0 B 0 B/s
     data_sent............: 0 B 0 B/s
     iteration_duration...: avg=4.6ms min=4.6ms med=4.6ms max=4.6ms p(90)=4.6ms p(95)=4.6ms
     iterations...........: 1   4.661324/s

Not sure if this is an issue or not but if I was running at high load it could well be?

3

Hi @BobRuub,
Sorry for the late reply.

I’d expect to see the property displayed, then the variables then a starting message, what i get is:

Your thought is legit in this case, as the doc here explains the k6 execution is not always linear between the various blocks. In this case, there are log lines from the init context that is a block of code executed in several places from the k6 engine, some following examples from your specific case:

  1. The first print comes from the execution of the code for resolving the exported Options.
  2. The transpiling code operation from Babel.
  3. The lines before the Starting... log come from the VU == 1 that executes the iterations
  4. The latest prints are from the VU for generating the Handle Summary

We have some ideas for making these steps more obvious, you can track and take a look into the following issues for details:

4

Thanks for the explanation.

I was expecting a framework to be like a program just because it looks like one, which in retrospect was a little dim.

I’ll go through the links your provided and I’m sure will gain a better understanding.