Ramping VUs executor does not properly executes a scenario after HardStop and Start

[stawr93]

Brief summary

I think I've encountered a bug in ramping-vus executor. I've been testing my application under a specific load profile when active users count increase and decrease sequentially few times. I need this to make sure that my application autoscaler works properly.

I was running tests in k8s cluster using k6-operator. And at some point I got all k6 worker pods killed with OOM error by k8s. It turns out such memory consumption was a side effect of the issue.

I noticed some VUs started to loop over my scenario executing only first step. I wasn't able to find out what is going wrong with them. But I was able to find a workaround by increasing gracefulRampDown parameter to make sure all VU iterations will be executed to the end. This fact made me think that in some cases executor which had received HardStop signal is no more able to execute a scenario properly.

k6 version

0.56, 0.57, 1.0.0-rc

OS

macOS, Ubuntu

Docker version and image (if applicable)

0.56, 0.57, 1.0.0-rc

Steps to reproduce the problem

Following script reproduces an issue:

import { check, sleep } from 'k6';
import exec from 'k6/execution';
import http from 'k6/http';
import { randomIntBetween } from 'https://jslib.k6.io/k6-utils/1.0.0/index.js';

export const options = {
    scenarios: {
        "default": {
            executor: "ramping-vus",
            startVUs: 1,
            gracefulRampDown: "0s",
            stages: [
                { duration: "2m", target: 20 },
                { duration: "2m", target: 10 },
                { duration: "2m", target: 20 },
                { duration: "2m", target: 0 }
            ]
        }
    }
};

export default async function () {
    const iterations = 10;

    for (let i = 0; i < 10; i++) {
        console.log(`[[vuNum=${exec.vu.idInInstance}]] Begin iteration #${i}`);
        const res = await http.asyncRequest("GET", "http://test.k6.io/?ts=" + Math.round(randomIntBetween(1,200)));
        console.log(`[[vuNum=${exec.vu.idInInstance}]] Middle of iteration #${i}`);
        let checkRes = check(res, {
            "Homepage welcome header present": (r) => r.body.indexOf("Welcome to the k6.io demo site!") !== -1
        });
        console.log(`[[vuNum=${exec.vu.idInInstance}]] Almost done iteration #${i}`);
        sleep(1 * i);
        console.log(`[[vuNum=${exec.vu.idInInstance}]] Done iteration #${i}`);
    }
}

function randomIntBetween(min, max) { // min and max included
    return Math.floor(Math.random() * (max - min + 1) + min);
}

Here is summary of test run:

k6 run -v --log-output=file=./k6.log script.js
time="2025-03-31T10:10:32+03:00" level=debug msg="Logger format: TEXT"

         /\      Grafana   /‾‾/  
    /\  /  \     |\  __   /  /   
   /  \/    \    | |/ /  /   ‾‾\ 
  /          \   |   (  |  (‾)  |
 / __________ \  |_|\_\  \_____/ 

     execution: local
        script: script.js
        output: -

     scenarios: (100.00%) 1 scenario, 20 max VUs, 8m0s max duration (incl. graceful stop):
              * default: Up to 20 looping VUs for 8m0s over 4 stages (gracefulRampDown: 0s, gracefulStop: 30s)


     ✓ Homepage welcome header present

     checks.........................: 100.00% 1127 out of 1127
     data_received..................: 36 MB   75 kB/s
     data_sent......................: 687 kB  1.4 kB/s
     http_req_blocked...............: avg=3.93ms   min=1µs      med=4µs      max=628.42ms p(90)=19µs     p(95)=39µs    
     http_req_connecting............: avg=2.33ms   min=0s       med=0s       max=380.6ms  p(90)=0s       p(95)=0s      
     http_req_duration..............: avg=197.51ms min=177.3ms  med=185.09ms max=1.53s    p(90)=192.17ms p(95)=202.89ms
       { expected_response:true }...: avg=197.51ms min=177.3ms  med=185.09ms max=1.53s    p(90)=192.17ms p(95)=202.89ms
     http_req_failed................: 0.00%   0 out of 6024
     http_req_receiving.............: avg=1.43ms   min=8µs      med=64µs     max=703.24ms p(90)=202µs    p(95)=313µs   
     http_req_sending...............: avg=33.48µs  min=3µs      med=14µs     max=9.73ms   p(90)=45µs     p(95)=79.84µs 
     http_req_tls_handshaking.......: avg=1.48ms   min=0s       med=0s       max=424.4ms  p(90)=0s       p(95)=0s      
     http_req_waiting...............: avg=196.04ms min=177.23ms med=184.94ms max=1.53s    p(90)=191.54ms p(95)=198.2ms 
     http_reqs......................: 6024    12.548834/s
     iteration_duration.............: avg=2.81s    min=359.87ms med=371.57ms max=50.77s   p(90)=556.12ms p(95)=1.73s   
     iterations.....................: 1980    4.124617/s
     vus............................: 1       min=1            max=20
     vus_max........................: 20      min=20           max=20


running (8m00.0s), 00/20 VUs, 1980 complete and 30 interrupted iterations
default ✓ [======================================] 00/20 VUs  8m0s

Full run log file: k6.log.

Here is a fragment of the log (as you can see, vuNum=20 repeatedly logs Begin iteration #0):

time="2025-03-31T10:14:45+03:00" level=info msg="[[vuNum=3]] Middle of iteration #0" source=console
time="2025-03-31T10:14:45+03:00" level=info msg="[[vuNum=3]] Almost done iteration #0" source=console
time="2025-03-31T10:14:45+03:00" level=info msg="[[vuNum=3]] Done iteration #0" source=console
time="2025-03-31T10:14:45+03:00" level=info msg="[[vuNum=3]] Begin iteration #1" source=console
time="2025-03-31T10:14:45+03:00" level=info msg="[[vuNum=6]] Done iteration #3" source=console
time="2025-03-31T10:14:45+03:00" level=info msg="[[vuNum=6]] Begin iteration #4" source=console
time="2025-03-31T10:14:45+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=4]] Middle of iteration #2" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=4]] Almost done iteration #2" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=3]] Middle of iteration #1" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=3]] Almost done iteration #1" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=6]] Middle of iteration #4" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=6]] Almost done iteration #4" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=1]] Done iteration #8" source=console
time="2025-03-31T10:14:46+03:00" level=info msg="[[vuNum=1]] Begin iteration #9" source=console
time="2025-03-31T10:14:47+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:47+03:00" level=info msg="[[vuNum=3]] Done iteration #1" source=console
time="2025-03-31T10:14:47+03:00" level=info msg="[[vuNum=3]] Begin iteration #2" source=console
time="2025-03-31T10:14:47+03:00" level=info msg="[[vuNum=1]] Middle of iteration #9" source=console
time="2025-03-31T10:14:47+03:00" level=info msg="[[vuNum=1]] Almost done iteration #9" source=console
time="2025-03-31T10:14:47+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:47+03:00" level=info msg="[[vuNum=3]] Middle of iteration #2" source=console
time="2025-03-31T10:14:47+03:00" level=info msg="[[vuNum=3]] Almost done iteration #2" source=console
time="2025-03-31T10:14:47+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=4]] Done iteration #2" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=4]] Begin iteration #3" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=13]] Done iteration #3" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=13]] Begin iteration #4" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=4]] Middle of iteration #3" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=4]] Almost done iteration #3" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=13]] Middle of iteration #4" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=13]] Almost done iteration #4" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=5]] Done iteration #7" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=5]] Begin iteration #8" source=console
time="2025-03-31T10:14:48+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:49+03:00" level=info msg="[[vuNum=5]] Middle of iteration #8" source=console
time="2025-03-31T10:14:49+03:00" level=info msg="[[vuNum=5]] Almost done iteration #8" source=console
time="2025-03-31T10:14:49+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console
time="2025-03-31T10:14:49+03:00" level=info msg="[[vuNum=3]] Done iteration #2" source=console
time="2025-03-31T10:14:49+03:00" level=info msg="[[vuNum=3]] Begin iteration #3" source=console
time="2025-03-31T10:14:49+03:00" level=info msg="[[vuNum=20]] Begin iteration #0" source=console

Expected behaviour

All non-interrupted iterations are completed properly, i.e. either failed or succeeded per scenario conditions.

Actual behaviour

Some of the iterations does not proceed to completion.

[inancgumus]

Hey @yorugac 👋 What do you think about this issue? Might it be related to k6-operator?

[stawr93]

@inancgumus, no, it's not related to k6-operator. You can run the script on your local machine and get the same behaviour.

[inancgumus]

@stawr93 Thank you 🙇 I'll check it out.