This repository was archived by the owner on Mar 18, 2025. It is now read-only.
This repository was archived by the owner on Mar 18, 2025. It is now read-only.
k6 standard output results are wrong when prometheus output is enabled #24
Description
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
mainDockerfile - 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?
Metadata
Metadata
Assignees
Labels
No labels