Hi! I've discovered some strange behaviour when prometheus output is enabled. The final test results seem to be wrong when prometheus output is enabled and the difference is quite substantial:
Example scenario:
import http from 'k6/http';
import { sleep } from 'k6';
export default function () {
http.get('https://example.com');
sleep(1);
http.get('https://example.com/foo');
sleep(1);
http.get('https://example.com/bar');
sleep(1);
}
Settings for k6:
- virtual users: 1
- duration: 10s
- k6 built from the latest
main
Dockerfile
- env variable:
K6_PROMETHEUS_REMOTE_URL=http://prometheus:9090/api/v1/write
- the same binary/environment used in both cases below
Assumptions
- the target site is very simple, it responds almost immediately
- having in mind the previous point, the average iteration time would be ~3 seconds and during the 10s duration of the whole test we should see ~3-4 iterations completed
- each iteration consists of 3 http requests, so overall number of requests would be ranging from 9 to 12
Case #1 - running without the prometheus output enabled
Command:
k6 run --vus 1 --duration 10s --tag source=example-site-test.js -- example-site-test.js
Output:
/\ |‾‾| /‾‾/ /‾‾/
/\ / \ | |/ / / /
/ \/ \ | ( / ‾‾\
/ \ | |\ \ | (‾) |
/ __________ \ |__| \__\ \_____/ .io
execution: local
script: example-site-test.js
output: -
scenarios: (100.00%) 1 scenario, 1 max VUs, 40s max duration (incl. graceful stop):
* default: 1 looping VUs for 10s (gracefulStop: 30s)
running (01.0s), 1/1 VUs, 0 complete and 0 interrupted iterations
default [ 10% ] 1 VUs 01.0s/10s
running (02.0s), 1/1 VUs, 0 complete and 0 interrupted iterations
default [ 20% ] 1 VUs 02.0s/10s
running (03.0s), 1/1 VUs, 0 complete and 0 interrupted iterations
default [ 30% ] 1 VUs 03.0s/10s
running (04.0s), 1/1 VUs, 1 complete and 0 interrupted iterations
default [ 40% ] 1 VUs 04.0s/10s
running (05.0s), 1/1 VUs, 1 complete and 0 interrupted iterations
default [ 50% ] 1 VUs 05.0s/10s
running (06.0s), 1/1 VUs, 1 complete and 0 interrupted iterations
default [ 60% ] 1 VUs 06.0s/10s
running (07.0s), 1/1 VUs, 2 complete and 0 interrupted iterations
default [ 70% ] 1 VUs 07.0s/10s
running (08.0s), 1/1 VUs, 2 complete and 0 interrupted iterations
default [ 80% ] 1 VUs 08.0s/10s
running (09.0s), 1/1 VUs, 2 complete and 0 interrupted iterations
default [ 90% ] 1 VUs 09.0s/10s
running (10.0s), 1/1 VUs, 3 complete and 0 interrupted iterations
default [ 100% ] 1 VUs 10.0s/10s
running (11.0s), 1/1 VUs, 3 complete and 0 interrupted iterations
default ↓ [ 100% ] 1 VUs 10s
running (12.0s), 1/1 VUs, 3 complete and 0 interrupted iterations
default ↓ [ 100% ] 1 VUs 10s
running (12.1s), 0/1 VUs, 4 complete and 0 interrupted iterations
default ✓ [ 100% ] 1 VUs 10s
data_received..................: 17 kB 1.4 kB/s
data_sent......................: 988 B 82 B/s
http_req_blocked...............: avg=4.86ms min=481ns med=821ns max=58.37ms p(90)=1.12µs p(95)=26.26ms
http_req_connecting............: avg=116.7µs min=0s med=0s max=1.4ms p(90)=0s p(95)=630.22µs
http_req_duration..............: avg=3.98ms min=3.14ms med=3.89ms max=4.91ms p(90)=4.8ms p(95)=4.89ms
{ expected_response:true }...: avg=3.98ms min=3.14ms med=3.89ms max=4.91ms p(90)=4.8ms p(95)=4.89ms
http_req_failed................: 0.00% ✓ 0 ✗ 12
http_req_receiving.............: avg=84.46µs min=65.65µs med=79.99µs max=136.04µs p(90)=92.44µs p(95)=112.27µs
http_req_sending...............: avg=117.82µs min=95.55µs med=110.21µs max=200.26µs p(90)=125.14µs p(95)=159.04µs
http_req_tls_handshaking.......: avg=1.69ms min=0s med=0s max=20.32ms p(90)=0s p(95)=9.14ms
http_req_waiting...............: avg=3.78ms min=2.93ms med=3.7ms max=4.69ms p(90)=4.5ms p(95)=4.62ms
http_reqs......................: 12 0.990406/s
iteration_duration.............: avg=3.02s min=3.01s med=3.01s max=3.07s p(90)=3.05s p(95)=3.06s
iterations.....................: 4 0.330135/s
vus............................: 1 min=1 max=1
vus_max........................: 1 min=1 max=1
Everything's correct - we have 4 iterations done, 12 http requests, it looks ok!
Case #2 - running with the prometheus output enabled
Command:
k6 run --vus 1 --duration 10s -o output-prometheus-remote --tag source=example-site-test.js -- example-site-test.js
Output:
/\ |‾‾| /‾‾/ /‾‾/
/\ / \ | |/ / / /
/ \/ \ | ( / ‾‾\
/ \ | |\ \ | (‾) |
/ __________ \ |__| \__\ \_____/ .io
time="2022-05-31T12:06:19Z" level=info msg="Prometheus: configuring remote-write with prometheus mapping"
execution: local
script: example-site-test.js
output: Output k6 metrics to prometheus remote-write endpoint
scenarios: (100.00%) 1 scenario, 1 max VUs, 40s max duration (incl. graceful stop):
* default: 1 looping VUs for 10s (gracefulStop: 30s)
running (01.0s), 1/1 VUs, 0 complete and 0 interrupted iterations
default [ 10% ] 1 VUs 01.0s/10s
running (02.0s), 1/1 VUs, 0 complete and 0 interrupted iterations
default [ 20% ] 1 VUs 02.0s/10s
running (03.0s), 1/1 VUs, 0 complete and 0 interrupted iterations
default [ 30% ] 1 VUs 03.0s/10s
running (04.0s), 1/1 VUs, 1 complete and 0 interrupted iterations
default [ 40% ] 1 VUs 04.0s/10s
running (05.0s), 1/1 VUs, 1 complete and 0 interrupted iterations
default [ 50% ] 1 VUs 05.0s/10s
running (06.0s), 1/1 VUs, 1 complete and 0 interrupted iterations
default [ 60% ] 1 VUs 06.0s/10s
running (07.0s), 1/1 VUs, 2 complete and 0 interrupted iterations
default [ 70% ] 1 VUs 07.0s/10s
running (08.0s), 1/1 VUs, 2 complete and 0 interrupted iterations
default [ 80% ] 1 VUs 08.0s/10s
running (09.0s), 1/1 VUs, 2 complete and 0 interrupted iterations
default [ 90% ] 1 VUs 09.0s/10s
running (10.0s), 1/1 VUs, 3 complete and 0 interrupted iterations
default [ 100% ] 1 VUs 10.0s/10s
running (11.0s), 1/1 VUs, 3 complete and 0 interrupted iterations
default ↓ [ 100% ] 1 VUs 10s
running (12.0s), 1/1 VUs, 3 complete and 0 interrupted iterations
default ↓ [ 100% ] 1 VUs 10s
running (12.1s), 0/1 VUs, 4 complete and 0 interrupted iterations
default ✓ [ 100% ] 1 VUs 10s
data_received..................: 30 kB 2.5 kB/s
data_sent......................: 1.9 kB 154 B/s
http_req_blocked...............: avg=3.91ms min=625ns med=928ns max=46.98ms p(90)=1.2µs p(95)=39.94ms
http_req_connecting............: avg=87.27µs min=0s med=0s max=1.04ms p(90)=0s p(95)=890.15µs
http_req_duration..............: avg=5.09ms min=3.53ms med=4.54ms max=7.65ms p(90)=7.64ms p(95)=7.65ms
{ expected_response:true }...: avg=5.09ms min=3.53ms med=4.54ms max=7.65ms p(90)=7.54ms p(95)=7.64ms
http_req_failed................: 0.00% ✓ 0 ✗ 24
http_req_receiving.............: avg=86.17µs min=64.84µs med=80.54µs max=153.48µs p(90)=96.78µs p(95)=144.98µs
http_req_sending...............: avg=120.22µs min=82.75µs med=115.69µs max=187.3µs p(90)=149.8µs p(95)=181.67µs
http_req_tls_handshaking.......: avg=2.12ms min=0s med=0s max=25.44ms p(90)=0s p(95)=21.62ms
http_req_waiting...............: avg=4.89ms min=3.36ms med=4.37ms max=7.45ms p(90)=7.3ms p(95)=7.42ms
http_reqs......................: 24 1.980191/s
iteration_duration.............: avg=3.03s min=3.01s med=3.02s max=3.06s p(90)=3.06s p(95)=3.06s
iterations.....................: 7 0.577556/s
vus............................: 1 min=1 max=1
vus_max........................: 1 min=1 max=1
Now it's getting weird - the final result shows 7 completed iterations (despite the fact that "progress bar" stopped at 4), 24 http requests, rates are also different. For some of the metrics there it looks like they're doubled (including data_received and data_sent) BUT in both cases (prometheus output enabled/disabled) the target service got the same number of requests - 12 (I checked that in logs of the target service).
I don't know what I'm doing wrong, could you check that please?