ramping-vus bug: gracefulStop is racing with iteration start

[nicodn]

k6 version

v0.34.1

OS

macOS & Linux

Docker version and image

No response

Expected Behaviour

Setting a stage, eg. via CLI args of --stage 30s:2 should utilize 2 vus during the test.

Actual Behaviour

The test report shows that only 1 vu was used. It behaves exactly the same as if I had set --stage 30s:1.

vus............................: 1       min=1      max=1
vus_max........................: 2       min=2      max=2

It seems the target number is exclusive of the last vu instead of inclusive when target > 1.

Steps to Reproduce the Problem

k6 run --stage 30s:2 yourtest.js

[na--]

The ramping-vus executor (for which stages is a shortcut option) linearly scales the number of looping VUs from its current VUs (either startVUs, as in your case that's 1 by default, or from the previous stage's target value) to the specified target value of the stage. The goal is to have exactly target running VUs at the end of the stage.

In your example, k6 will actually start up the second VU right at t=30s, but it will immediately stop it right after that, before it can even start a single iteration. If add another stage with 2 VUs in your test (e.g. k6 run --stage 30s:2 --stage 10s:2 script.js), you'll see that this second VU will actually run some iterations.

That said, I think we still have a minor bug with the handling of this... 😞 If this script:

import { sleep } from 'k6';
import exec from 'k6/execution';

export const options = {
    stages: [
        { duration: '30s', target: 2 },
    ]
}

export default function () {
    console.log(`[t=${(new Date()) - exec.scenario.startTime}ms] VU{${exec.vu.idInInstance}/${exec.vu.idInTest}} ran scenario iteration ${exec.scenario.iterationInTest} (${exec.vu.iterationInScenario} for VU) in ${exec.scenario.name}`);
    sleep(1);
} 

Is executed with k6 run --verbose, we'll see something like this:

...
DEBU[0000] Initialization starting...                    component=engine
DEBU[0000] Start of initialization                       executorsCount=1 neededVUs=2 phase=local-execution-scheduler-init
DEBU[0000] Initialized VU #1                             phase=local-execution-scheduler-init
DEBU[0000] Initialized VU #2                             phase=local-execution-scheduler-init
DEBU[0000] Finished initializing needed VUs, start initializing executors...  phase=local-execution-scheduler-init
DEBU[0000] Initialized executor default                  phase=local-execution-scheduler-init
DEBU[0000] Initialization completed                      phase=local-execution-scheduler-init
DEBU[0000] Execution scheduler starting...               component=engine
DEBU[0000] Start of test run                             executorsCount=1 phase=local-execution-scheduler-run
DEBU[0000] Running setup()                               phase=local-execution-scheduler-run
DEBU[0000] Metrics processing started...                 component=engine
DEBU[0000] Starting emission of VU metrics...            component=engine
DEBU[0000] Start all executors...                        phase=local-execution-scheduler-run
DEBU[0000] Starting executor                             executor=default startTime=0s type=ramping-vus
DEBU[0000] Starting executor run...                      duration=30s executor=ramping-vus maxVUs=2 numStages=1 scenario=default startVUs=1 type=ramping-vus
DEBU[0000] Start                                         executor=ramping-vus scenario=default vuNum=0
INFO[0000] [t=0ms] VU{1/1} ran scenario iteration 0 (0 for VU) in default  source=console
INFO[0001] [t=1001ms] VU{1/1} ran scenario iteration 1 (1 for VU) in default  source=console
INFO[0002] [t=2002ms] VU{1/1} ran scenario iteration 2 (2 for VU) in default  source=console
INFO[0003] [t=3003ms] VU{1/1} ran scenario iteration 3 (3 for VU) in default  source=console
INFO[0004] [t=4004ms] VU{1/1} ran scenario iteration 4 (4 for VU) in default  source=console
INFO[0005] [t=5006ms] VU{1/1} ran scenario iteration 5 (5 for VU) in default  source=console
INFO[0006] [t=6006ms] VU{1/1} ran scenario iteration 6 (6 for VU) in default  source=console
INFO[0007] [t=7007ms] VU{1/1} ran scenario iteration 7 (7 for VU) in default  source=console
INFO[0008] [t=8008ms] VU{1/1} ran scenario iteration 8 (8 for VU) in default  source=console
INFO[0009] [t=9009ms] VU{1/1} ran scenario iteration 9 (9 for VU) in default  source=console
INFO[0010] [t=10009ms] VU{1/1} ran scenario iteration 10 (10 for VU) in default  source=console
INFO[0011] [t=11009ms] VU{1/1} ran scenario iteration 11 (11 for VU) in default  source=console
INFO[0012] [t=12010ms] VU{1/1} ran scenario iteration 12 (12 for VU) in default  source=console
INFO[0013] [t=13011ms] VU{1/1} ran scenario iteration 13 (13 for VU) in default  source=console
INFO[0014] [t=14012ms] VU{1/1} ran scenario iteration 14 (14 for VU) in default  source=console
INFO[0015] [t=15013ms] VU{1/1} ran scenario iteration 15 (15 for VU) in default  source=console
INFO[0016] [t=16014ms] VU{1/1} ran scenario iteration 16 (16 for VU) in default  source=console
INFO[0017] [t=17014ms] VU{1/1} ran scenario iteration 17 (17 for VU) in default  source=console
INFO[0018] [t=18016ms] VU{1/1} ran scenario iteration 18 (18 for VU) in default  source=console
INFO[0019] [t=19016ms] VU{1/1} ran scenario iteration 19 (19 for VU) in default  source=console
INFO[0020] [t=20017ms] VU{1/1} ran scenario iteration 20 (20 for VU) in default  source=console
INFO[0021] [t=21018ms] VU{1/1} ran scenario iteration 21 (21 for VU) in default  source=console
INFO[0022] [t=22019ms] VU{1/1} ran scenario iteration 22 (22 for VU) in default  source=console
INFO[0023] [t=23020ms] VU{1/1} ran scenario iteration 23 (23 for VU) in default  source=console
INFO[0024] [t=24022ms] VU{1/1} ran scenario iteration 24 (24 for VU) in default  source=console
INFO[0025] [t=25023ms] VU{1/1} ran scenario iteration 25 (25 for VU) in default  source=console
INFO[0026] [t=26023ms] VU{1/1} ran scenario iteration 26 (26 for VU) in default  source=console
INFO[0027] [t=27025ms] VU{1/1} ran scenario iteration 27 (27 for VU) in default  source=console
INFO[0028] [t=28025ms] VU{1/1} ran scenario iteration 28 (28 for VU) in default  source=console
INFO[0029] [t=29026ms] VU{1/1} ran scenario iteration 29 (29 for VU) in default  source=console
DEBU[0030] Start                                         executor=ramping-vus scenario=default vuNum=1
DEBU[0030] Regular duration is done, waiting for iterations to gracefully finish  executor=ramping-vus gracefulStop=30s scenario=default
DEBU[0030] Graceful stop                                 executor=ramping-vus scenario=default vuNum=0
DEBU[0030] Graceful stop                                 executor=ramping-vus scenario=default vuNum=1
DEBU[0030] Executor finished successfully                executor=default startTime=0s type=ramping-vus
DEBU[0030] Running teardown()                            phase=local-execution-scheduler-run
DEBU[0030] Execution scheduler terminated                component=engine error="<nil>"
DEBU[0030] Processing metrics and thresholds after the test run has ended...  component=engine
DEBU[0030] Engine run terminated cleanly    
...

So, as I said, k6 actually starts the second VU at t=30s, but then immediately stops it, whereas I'd expect it to make at least a single iteration because of the default gracefulStop of 30s 😕

DEBU[0030] Start                                         executor=ramping-vus scenario=default vuNum=1
DEBU[0030] Regular duration is done, waiting for iterations to gracefully finish  executor=ramping-vus gracefulStop=30s scenario=default
DEBU[0030] Graceful stop                                 executor=ramping-vus scenario=default vuNum=0
DEBU[0030] Graceful stop                                 executor=ramping-vus scenario=default vuNum=1
DEBU[0030] Executor finished successfully                executor=default startTime=0s type=ramping-vus

So yeah, the ramping up is working as intended, we briefly get 2 VUs at t=30s. Unfortunately, it seems like we have a minor bug with the implementation of gracefulStop, it is probably racing with the start of iterations code... 😞 I don't think this would matter all that much in practice, but it's still not working exactly as expected, so we should fix it after merging #2155.

Thanks for opening this issue, @nicodn! I'll adjust the title to reflect my findings.