k6
k6 copied to clipboard
grafana
Negative http_req_receiving values
Reported in https://stackoverflow.com/questions/66368090/k6-https-k6-io-tool-reports-negative-http-req-duration-time with k6 v0.30.0:
checks.....................: 0.00% ✓ 0 ✗ 133631
data_received..............: 18 MB 1.8 MB/s
data_sent..................: 10 MB 1.0 MB/s
http_req_blocked...........: avg=47.03µs min=13.6µs med=20.8µs max=46.11ms p(90)=27.1µs p(95)=33.5µs
http_req_connecting........: avg=3.96µs min=0s med=0s max=34.35ms p(90)=0s p(95)=0s
✓ http_req_duration..........: avg=14.05ms min=-15.7758ms med=11.71ms max=163.09ms p(90)=27.25ms p(95)=33.93ms
http_req_receiving.........: avg=108.11µs min=-34.2818ms med=48.4µs max=87.86ms p(90)=83.3µs p(95)=112.6µs
http_req_sending...........: avg=47.79µs min=11.6µs med=20.5µs max=56.39ms p(90)=32.8µs p(95)=45.6µs
http_req_tls_handshaking...: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
http_req_waiting...........: avg=13.89ms min=0s med=11.56ms max=163.01ms p(90)=27.02ms p(95)=33.66ms
http_reqs..................: 133631 13350.537278/s
iteration_duration.........: avg=14.9ms min=287.4µs med=12.32ms max=227.44ms p(90)=28.72ms p(95)=35.79ms
iterations.................: 133631 13350.537278/s
vus........................: 200 min=200 max=200
vus_max....................: 200 min=200 max=200
Previously, we've had issues like this with HTTP/2 measurements (e.g. the server starts returning a response before it has completely processes the whole request we're sending it) or with strange connection reuse happened (e.g. an already established network connection gets freed and immediately reused by the HTTP client while it was in the middle of establishing a new connection). I thought we had fixed all of these issues, but this looks like it could be the former.
hello, thanks for a prompt response I have added a few details and attached docker-compose file to reproduce the issue here https://github.com/ludenus/k6-issue-1872
I ran the example repo on my machine and couldn't reproduce the issue :confused: First I somewhat modified the script to be able to run it with 2000 VUs on my laptop, so I ran this with K6_COMPATIBILITY_MODE: "base" (docs):
var http = require('k6/http');
var check = require('k6').check;
exports.options = {
thresholds: {
http_req_duration: ['avg < 200', 'p(99)<1000', 'p(99.999)<1000'],
},
};
exports.default = function () {
var res = http.get('http://pong/ping/k6');
check(res, {
'is status 200': function(r) { return r.status === 200; },
'is duration <= 1000ms': function(r) { return r.http_req_duration < 1000; },
});
}
And it resulted in this:
k6_1 | checks.....................: 50.00% ✓ 1395838 ✗ 1395838
k6_1 | data_received..............: 190 MB 1.9 MB/s
k6_1 | data_sent..................: 108 MB 1.1 MB/s
k6_1 | http_req_blocked...........: avg=217.2µs min=1.87µs med=3.55µs max=354.11ms p(90)=4.57µs p(95)=5.23µs
k6_1 | http_req_connecting........: avg=90.13µs min=0s med=0s max=163.36ms p(90)=0s p(95)=0s
k6_1 | ✓ http_req_duration..........: avg=113.41ms min=121.46µs med=101.23ms max=827.13ms p(90)=159.74ms p(95)=246.7ms
k6_1 | http_req_receiving.........: avg=796.46µs min=12.69µs med=20.2µs max=398.31ms p(90)=39.55µs p(95)=203.49µs
k6_1 | http_req_sending...........: avg=160.83µs min=5.74µs med=8.29µs max=412.5ms p(90)=15.94µs p(95)=67.64µs
k6_1 | http_req_tls_handshaking...: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
k6_1 | http_req_waiting...........: avg=112.46ms min=85.2µs med=101.02ms max=578.31ms p(90)=158.68ms p(95)=243.82ms
k6_1 | http_reqs..................: 1395838 13942.148485/s
k6_1 | iteration_duration.........: avg=142.51ms min=1.43ms med=115.59ms max=864.27ms p(90)=249.44ms p(95)=318.89ms
k6_1 | iterations.................: 1395838 13942.148485/s
k6_1 | vus........................: 1 min=1 max=2000
k6_1 | vus_max....................: 2000 min=2000 max=2000
Them I ran the original, exactly as it is in the repo, just with 200 VUs, and got this:
k6_1 | checks.....................: 50.00% ✓ 1304842 ✗ 1304842
k6_1 | data_received..............: 178 MB 1.8 MB/s
k6_1 | data_sent..................: 100 MB 1.0 MB/s
k6_1 | http_req_blocked...........: avg=9.56µs min=1.8µs med=3.26µs max=33.71ms p(90)=4.58µs p(95)=5.35µs
k6_1 | http_req_connecting........: avg=518ns min=0s med=0s max=11.31ms p(90)=0s p(95)=0s
k6_1 | ✓ http_req_duration..........: avg=13.17ms min=89.44µs med=10.91ms max=142.08ms p(90)=26.46ms p(95)=31.67ms
k6_1 | http_req_receiving.........: avg=76.3µs min=9.88µs med=20.5µs max=106.79ms p(90)=34.76µs p(95)=47.87µs
k6_1 | http_req_sending...........: avg=23µs min=4.97µs med=7.99µs max=76.18ms p(90)=14.66µs p(95)=18.83µs
k6_1 | http_req_tls_handshaking...: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
k6_1 | http_req_waiting...........: avg=13.07ms min=67.78µs med=10.83ms max=141.78ms p(90)=26.3ms p(95)=31.46ms
k6_1 | http_reqs..................: 1304842 13022.728609/s
k6_1 | iteration_duration.........: avg=15.33ms min=139.7µs med=12.16ms max=270.02ms p(90)=29.35ms p(95)=36.2ms
k6_1 | iterations.................: 1304842 13022.728609/s
k6_1 | vus........................: 200 min=200 max=200
k6_1 | vus_max....................: 200 min=200 max=200
I ran the second test a few more times, just to be sure, similar results - no negative http_req_receiving... :confused: @ludenus, how reproducible is the problem on your machine? I am running on Linux, so maybe this has something to do with Docker networking on Macs maybe? :man_shrugging:
hello @na-- I have just reproduced the issue with the script you propose and --compatibility-mode=base k6 option
From 10 measurements I get 6 that contain a negative number for one of the http_req_receiving or http_req_sending metric (sometimes they both are negative).
k6_1 | running (1m40.1s), 0000/2000 VUs, 1106397 complete and 0 interrupted iterations
k6_1 | default ✓ [ 100% ] 2000 VUs 1m40s
k6_1 |
k6_1 | ✓ is status 200
k6_1 | ✗ is duration <= 1000ms
k6_1 | ↳ 0% — ✓ 0 / ✗ 1106397
k6_1 |
k6_1 | checks.....................: 50.00% ✓ 1106397 ✗ 1106397
k6_1 | data_received..............: 150 MB 1.5 MB/s
k6_1 | data_sent..................: 85 MB 852 kB/s
k6_1 | http_req_blocked...........: avg=347.54µs min=0s med=22.7µs max=1.2s p(90)=30.2µs p(95)=37.7µs
k6_1 | http_req_connecting........: avg=274.73µs min=0s med=0s max=1.19s p(90)=0s p(95)=0s
k6_1 | ✓ http_req_duration..........: avg=106.12ms min=79.4µs med=100.45ms max=714.36ms p(90)=158.85ms p(95)=188.56ms
k6_1 | http_req_receiving.........: avg=1.12ms min=-34.5252ms med=59µs max=493.26ms p(90)=139µs p(95)=309µs
k6_1 | http_req_sending...........: avg=480.45µs min=-34.525ms med=23.8µs max=448.33ms p(90)=42.7µs p(95)=100.8µs
k6_1 | http_req_tls_handshaking...: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
k6_1 | http_req_waiting...........: avg=104.51ms min=0s med=99.68ms max=604.5ms p(90)=156.26ms p(95)=183.64ms
k6_1 | http_reqs..................: 1106397 11057.867627/s
k6_1 | iteration_duration.........: avg=173.81ms min=560.8µs med=154ms max=1.53s p(90)=287.87ms p(95)=355.22ms
k6_1 | iterations.................: 1106397 11057.867627/s
k6_1 | vus........................: 1658 min=1658 max=2000
k6_1 | vus_max....................: 2000 min=2000 max=2000
k6_1 |
perf_k6_1 exited with code 0
I will recheck on Linux host later and let you know.
@ludenus can you please run your test again, but with this script:
var http = require('k6/http');
var check = require('k6').check;
exports.options = {
thresholds: {
http_req_duration: ['avg < 200', 'p(99)<1000', 'p(99.999)<1000'],
},
};
exports.default = function () {
var resp = http.get('http://pong/ping/k6');
var ok = check(resp, {
'is status 200': function (r) { return r.status === 200; },
'is http_req_receiving >= 0': function (r) { return r.timings.receiving >= 0; },
});
if (!ok) {
console.log(JSON.stringify(resp, null, 4));
}
}
it should print the details of every request-response where http_req_receiving was less than zero.
sure, here it is
√ ~/wrk/perf
% docker-compose -f ./docker-compose.k6.yaml up
Creating network "perf_default" with the default driver
Creating perf_pong_1 ... done
Creating perf_k6_1 ... done
Attaching to perf_pong_1, perf_k6_1
pong_1 | Now listening on: http://localhost:80
pong_1 | Application started. Press CTRL+C to shut down.
k6_1 |
k6_1 | /\ |‾‾| /‾‾/ /‾‾/
k6_1 | /\ / \ | |/ / / /
k6_1 | / \/ \ | ( / ‾‾\
k6_1 | / \ | |\ \ | (‾) |
k6_1 | / __________ \ |__| \__\ \_____/ .io
k6_1 |
k6_1 | execution: local
k6_1 | script: /script.js
k6_1 | output: -
k6_1 |
k6_1 | scenarios: (100.00%) 1 scenario, 2000 max VUs, 2m10s max duration (incl. graceful stop):
k6_1 | * default: 2000 looping VUs for 1m40s (gracefulStop: 30s)
k6_1 |
k6_1 |
k6_1 | running (0m00.3s), 2000/2000 VUs, 142 complete and 0 interrupted iterations
k6_1 | default [ 0% ] 2000 VUs 0m00.3s/1m40s
...
k6_1 |
k6_1 | running (0m36.3s), 2000/2000 VUs, 398661 complete and 0 interrupted iterations
k6_1 | default [ 36% ] 2000 VUs 0m36.3s/1m40s
k6_1 | time="2021-02-26T09:15:11Z" level=info msg="{\n \"remote_ip\": \"172.19.0.2\",\n \"remote_port\": 80,\n \"url\": \"http://pong/ping/k6\",\n \"status\": 200,\n \"status_text\": \"200 OK\",\n \"proto\": \"HTTP/1.1\",\n \"headers\": {\n \"Content-Type\": \"application/json; charset=UTF-8\",\n \"Date\": \"Fri, 26 Feb 2021 09:15:11 GMT\",\n \"Content-Length\": \"13\"\n },\n \"cookies\": {},\n \"body\": \"{\\\"pong\\\":\\\"k6\\\"}\",\n \"timings\": {\n \"duration\": 81.4798,\n \"blocked\": 0.0213,\n \"looking_up\": 0,\n \"connecting\": 0,\n \"tls_handshaking\": 0,\n \"sending\": 0.0238,\n \"waiting\": 92.5957,\n \"receiving\": -11.1397\n },\n \"tls_version\": \"\",\n \"tls_cipher_suite\": \"\",\n \"ocsp\": {\n \"produced_at\": 0,\n \"this_update\": 0,\n \"next_update\": 0,\n \"revoked_at\": 0,\n \"revocation_reason\": \"\",\n \"status\": \"\"\n },\n \"error\": \"\",\n \"error_code\": 0,\n \"request\": {\n \"method\": \"GET\",\n \"url\": \"http://pong/ping/k6\",\n \"headers\": {\n \"User-Agent\": [\n \"k6/0.30.0 (https://k6.io/)\"\n ]\n },\n \"body\": \"\",\n \"cookies\": {}\n }\n}" source=console
k6_1 | time="2021-02-26T09:15:12Z" level=info msg="{\n \"remote_ip\": \"172.19.0.2\",\n \"remote_port\": 80,\n \"url\": \"http://pong/ping/k6\",\n \"status\": 200,\n \"status_text\": \"200 OK\",\n \"proto\": \"HTTP/1.1\",\n \"headers\": {\n \"Content-Type\": \"application/json; charset=UTF-8\",\n \"Date\": \"Fri, 26 Feb 2021 09:15:11 GMT\",\n \"Content-Length\": \"13\"\n },\n \"cookies\": {},\n \"body\": \"{\\\"pong\\\":\\\"k6\\\"}\",\n \"timings\": {\n \"duration\": 42.0096,\n \"blocked\": 0.0238,\n \"looking_up\": 0,\n \"connecting\": 0,\n \"tls_handshaking\": 0,\n \"sending\": 0.0381,\n \"waiting\": 69.6788,\n \"receiving\": -27.7073\n },\n \"tls_version\": \"\",\n \"tls_cipher_suite\": \"\",\n \"ocsp\": {\n \"produced_at\": 0,\n \"this_update\": 0,\n \"next_update\": 0,\n \"revoked_at\": 0,\n \"revocation_reason\": \"\",\n \"status\": \"\"\n },\n \"error\": \"\",\n \"error_code\": 0,\n \"request\": {\n \"method\": \"GET\",\n \"url\": \"http://pong/ping/k6\",\n \"headers\": {\n \"User-Agent\": [\n \"k6/0.30.0 (https://k6.io/)\"\n ]\n },\n \"body\": \"\",\n \"cookies\": {}\n }\n}" source=console
k6_1 |
k6_1 | running (0m37.2s), 2000/2000 VUs, 410673 complete and 0 interrupted iterations
k6_1 | default [ 37% ] 2000 VUs 0m37.3s/1m40s
k6_1 | time="2021-02-26T09:15:12Z" level=info msg="{\n \"remote_ip\": \"172.19.0.2\",\n \"remote_port\": 80,\n \"url\": \"http://pong/ping/k6\",\n \"status\": 200,\n \"status_text\": \"200 OK\",\n \"proto\": \"HTTP/1.1\",\n \"headers\": {\n \"Date\": \"Fri, 26 Feb 2021 09:15:11 GMT\",\n \"Content-Length\": \"13\",\n \"Content-Type\": \"application/json; charset=UTF-8\"\n },\n \"cookies\": {},\n \"body\": \"{\\\"pong\\\":\\\"k6\\\"}\",\n \"timings\": {\n \"duration\": 88.9084,\n \"blocked\": 0.0242,\n \"looking_up\": 0,\n \"connecting\": 0,\n \"tls_handshaking\": 0,\n \"sending\": 0.0232,\n \"waiting\": 105.644,\n \"receiving\": -16.7588\n },\n \"tls_version\": \"\",\n \"tls_cipher_suite\": \"\",\n \"ocsp\": {\n \"produced_at\": 0,\n \"this_update\": 0,\n \"next_update\": 0,\n \"revoked_at\": 0,\n \"revocation_reason\": \"\",\n \"status\": \"\"\n },\n \"error\": \"\",\n \"error_code\": 0,\n \"request\": {\n \"method\": \"GET\",\n \"url\": \"http://pong/ping/k6\",\n \"headers\": {\n \"User-Agent\": [\n \"k6/0.30.0 (https://k6.io/)\"\n ]\n },\n \"body\": \"\",\n \"cookies\": {}\n }\n}" source=console
k6_1 |
k6_1 | running (0m38.2s), 2000/2000 VUs, 421529 complete and 0 interrupted iterations
k6_1 | default [ 38% ] 2000 VUs 0m38.3s/1m40s
...
k6_1 |
k6_1 | running (1m06.2s), 2000/2000 VUs, 699576 complete and 0 interrupted iterations
k6_1 | default [ 66% ] 2000 VUs 1m06.3s/1m40s
k6_1 | time="2021-02-26T09:15:41Z" level=info msg="{\n \"remote_ip\": \"172.19.0.2\",\n \"remote_port\": 80,\n \"url\": \"http://pong/ping/k6\",\n \"status\": 200,\n \"status_text\": \"200 OK\",\n \"proto\": \"HTTP/1.1\",\n \"headers\": {\n \"Content-Type\": \"application/json; charset=UTF-8\",\n \"Date\": \"Fri, 26 Feb 2021 09:15:41 GMT\",\n \"Content-Length\": \"13\"\n },\n \"cookies\": {},\n \"body\": \"{\\\"pong\\\":\\\"k6\\\"}\",\n \"timings\": {\n \"duration\": 163.3468,\n \"blocked\": 0.0295,\n \"looking_up\": 0,\n \"connecting\": 0,\n \"tls_handshaking\": 0,\n \"sending\": 0.0296,\n \"waiting\": 196.8227,\n \"receiving\": -33.5055\n },\n \"tls_version\": \"\",\n \"tls_cipher_suite\": \"\",\n \"ocsp\": {\n \"produced_at\": 0,\n \"this_update\": 0,\n \"next_update\": 0,\n \"revoked_at\": 0,\n \"revocation_reason\": \"\",\n \"status\": \"\"\n },\n \"error\": \"\",\n \"error_code\": 0,\n \"request\": {\n \"method\": \"GET\",\n \"url\": \"http://pong/ping/k6\",\n \"headers\": {\n \"User-Agent\": [\n \"k6/0.30.0 (https://k6.io/)\"\n ]\n },\n \"body\": \"\",\n \"cookies\": {}\n }\n}" source=console
k6_1 |
k6_1 | running (1m07.2s), 2000/2000 VUs, 707133 complete and 0 interrupted iterations
k6_1 | default [ 67% ] 2000 VUs 1m07.3s/1m40s
k6_1 | time="2021-02-26T09:15:42Z" level=info msg="{\n \"remote_ip\": \"172.19.0.2\",\n \"remote_port\": 80,\n \"url\": \"http://pong/ping/k6\",\n \"status\": 200,\n \"status_text\": \"200 OK\",\n \"proto\": \"HTTP/1.1\",\n \"headers\": {\n \"Date\": \"Fri, 26 Feb 2021 09:15:41 GMT\",\n \"Content-Length\": \"13\",\n \"Content-Type\": \"application/json; charset=UTF-8\"\n },\n \"cookies\": {},\n \"body\": \"{\\\"pong\\\":\\\"k6\\\"}\",\n \"timings\": {\n \"duration\": 162.9286,\n \"blocked\": 0.0286,\n \"looking_up\": 0,\n \"connecting\": 0,\n \"tls_handshaking\": 0,\n \"sending\": 0.0265,\n \"waiting\": 167.0958,\n \"receiving\": -4.1937\n },\n \"tls_version\": \"\",\n \"tls_cipher_suite\": \"\",\n \"ocsp\": {\n \"produced_at\": 0,\n \"this_update\": 0,\n \"next_update\": 0,\n \"revoked_at\": 0,\n \"revocation_reason\": \"\",\n \"status\": \"\"\n },\n \"error\": \"\",\n \"error_code\": 0,\n \"request\": {\n \"method\": \"GET\",\n \"url\": \"http://pong/ping/k6\",\n \"headers\": {\n \"User-Agent\": [\n \"k6/0.30.0 (https://k6.io/)\"\n ]\n },\n \"body\": \"\",\n \"cookies\": {}\n }\n}" source=console
k6_1 | time="2021-02-26T09:15:42Z" level=info msg="{\n \"remote_ip\": \"172.19.0.2\",\n \"remote_port\": 80,\n \"url\": \"http://pong/ping/k6\",\n \"status\": 200,\n \"status_text\": \"200 OK\",\n \"proto\": \"HTTP/1.1\",\n \"headers\": {\n \"Content-Type\": \"application/json; charset=UTF-8\",\n \"Date\": \"Fri, 26 Feb 2021 09:15:41 GMT\",\n \"Content-Length\": \"13\"\n },\n \"cookies\": {},\n \"body\": \"{\\\"pong\\\":\\\"k6\\\"}\",\n \"timings\": {\n \"duration\": 191.153,\n \"blocked\": 0.0336,\n \"looking_up\": 0,\n \"connecting\": 0,\n \"tls_handshaking\": 0,\n \"sending\": 0.0626,\n \"waiting\": 199.7006,\n \"receiving\": -8.6102\n },\n \"tls_version\": \"\",\n \"tls_cipher_suite\": \"\",\n \"ocsp\": {\n \"produced_at\": 0,\n \"this_update\": 0,\n \"next_update\": 0,\n \"revoked_at\": 0,\n \"revocation_reason\": \"\",\n \"status\": \"\"\n },\n \"error\": \"\",\n \"error_code\": 0,\n \"request\": {\n \"method\": \"GET\",\n \"url\": \"http://pong/ping/k6\",\n \"headers\": {\n \"User-Agent\": [\n \"k6/0.30.0 (https://k6.io/)\"\n ]\n },\n \"body\": \"\",\n \"cookies\": {}\n }\n}" source=console
k6_1 |
k6_1 | running (1m08.2s), 2000/2000 VUs, 712356 complete and 0 interrupted iterations
...
k6_1 |
k6_1 | running (1m36.2s), 2000/2000 VUs, 1015207 complete and 0 interrupted iterations
k6_1 | default [ 96% ] 2000 VUs 1m36.3s/1m40s
k6_1 | time="2021-02-26T09:16:11Z" level=info msg="{\n \"remote_ip\": \"172.19.0.2\",\n \"remote_port\": 80,\n \"url\": \"http://pong/ping/k6\",\n \"status\": 200,\n \"status_text\": \"200 OK\",\n \"proto\": \"HTTP/1.1\",\n \"headers\": {\n \"Content-Type\": \"application/json; charset=UTF-8\",\n \"Date\": \"Fri, 26 Feb 2021 09:16:11 GMT\",\n \"Content-Length\": \"13\"\n },\n \"cookies\": {},\n \"body\": \"{\\\"pong\\\":\\\"k6\\\"}\",\n \"timings\": {\n \"duration\": 25.157,\n \"blocked\": 0.0935,\n \"looking_up\": 0,\n \"connecting\": 0,\n \"tls_handshaking\": 0,\n \"sending\": 0.0287,\n \"waiting\": 28.694,\n \"receiving\": -3.5657\n },\n \"tls_version\": \"\",\n \"tls_cipher_suite\": \"\",\n \"ocsp\": {\n \"produced_at\": 0,\n \"this_update\": 0,\n \"next_update\": 0,\n \"revoked_at\": 0,\n \"revocation_reason\": \"\",\n \"status\": \"\"\n },\n \"error\": \"\",\n \"error_code\": 0,\n \"request\": {\n \"method\": \"GET\",\n \"url\": \"http://pong/ping/k6\",\n \"headers\": {\n \"User-Agent\": [\n \"k6/0.30.0 (https://k6.io/)\"\n ]\n },\n \"body\": \"\",\n \"cookies\": {}\n }\n}" source=console
k6_1 | time="2021-02-26T09:16:11Z" level=info msg="{\n \"remote_ip\": \"172.19.0.2\",\n \"remote_port\": 80,\n \"url\": \"http://pong/ping/k6\",\n \"status\": 200,\n \"status_text\": \"200 OK\",\n \"proto\": \"HTTP/1.1\",\n \"headers\": {\n \"Date\": \"Fri, 26 Feb 2021 09:16:11 GMT\",\n \"Content-Length\": \"13\",\n \"Content-Type\": \"application/json; charset=UTF-8\"\n },\n \"cookies\": {},\n \"body\": \"{\\\"pong\\\":\\\"k6\\\"}\",\n \"timings\": {\n \"duration\": 53.5901,\n \"blocked\": 0.0294,\n \"looking_up\": 0,\n \"connecting\": 0,\n \"tls_handshaking\": 0,\n \"sending\": 0.0312,\n \"waiting\": 58.0011,\n \"receiving\": -4.4422\n },\n \"tls_version\": \"\",\n \"tls_cipher_suite\": \"\",\n \"ocsp\": {\n \"produced_at\": 0,\n \"this_update\": 0,\n \"next_update\": 0,\n \"revoked_at\": 0,\n \"revocation_reason\": \"\",\n \"status\": \"\"\n },\n \"error\": \"\",\n \"error_code\": 0,\n \"request\": {\n \"method\": \"GET\",\n \"url\": \"http://pong/ping/k6\",\n \"headers\": {\n \"User-Agent\": [\n \"k6/0.30.0 (https://k6.io/)\"\n ]\n },\n \"body\": \"\",\n \"cookies\": {}\n }\n}" source=console
k6_1 |
...
k6_1 |
k6_1 | running (1m40.0s), 0000/2000 VUs, 1055790 complete and 0 interrupted iterations
k6_1 | default ✓ [ 100% ] 2000 VUs 1m40s
k6_1 |
k6_1 | ✓ is status 200
k6_1 | ✗ is http_req_receiving >= 0
k6_1 | ↳ 99% — ✓ 1055782 / ✗ 8
k6_1 |
k6_1 | checks.....................: 99.99% ✓ 2111572 ✗ 8
k6_1 | data_received..............: 144 MB 1.4 MB/s
k6_1 | data_sent..................: 81 MB 813 kB/s
k6_1 | http_req_blocked...........: avg=1.12ms min=0s med=23.7µs max=3.18s p(90)=31.3µs p(95)=39.3µs
k6_1 | http_req_connecting........: avg=1.03ms min=0s med=0s max=3.18s p(90)=0s p(95)=0s
k6_1 | ✓ http_req_duration..........: avg=111.83ms min=197.7µs med=103.46ms max=1.01s p(90)=170.35ms p(95)=208.6ms
k6_1 | http_req_receiving.........: avg=1.19ms min=-33.505499ms med=59.7µs max=390.04ms p(90)=154.5µs p(95)=335µs
k6_1 | http_req_sending...........: avg=555.45µs min=-34.3892ms med=24.3µs max=417.19ms p(90)=48.3µs p(95)=112.2µs
k6_1 | http_req_tls_handshaking...: avg=0s min=0s med=0s max=0s p(90)=0s p(95)=0s
k6_1 | http_req_waiting...........: avg=110.08ms min=129.89µs med=102.66ms max=1.01s p(90)=167.5ms p(95)=203.35ms
k6_1 | http_reqs..................: 1055790 10555.615079/s
k6_1 | iteration_duration.........: avg=182.12ms min=482.1µs med=157.89ms max=3.27s p(90)=307.92ms p(95)=377.09ms
k6_1 | iterations.................: 1055790 10555.615079/s
k6_1 | vus........................: 2000 min=2000 max=2000
k6_1 | vus_max....................: 2000 min=2000 max=2000
k6_1 |
perf_k6_1 exited with code 0
Here they are after some formatting:
{
"remote_ip": "172.19.0.2",
"remote_port": 80,
"url": "http://pong/ping/k6",
"status": 200,
"status_text": "200 OK",
"proto": "HTTP/1.1",
"headers": {
"Content-Type": "application/json; charset=UTF-8",
"Date": "Fri, 26 Feb 2021 09:15:11 GMT",
"Content-Length": "13"
},
"cookies": {},
"body": "{\"pong\":\"k6\"}",
"timings": {
"duration": 81.4798,
"blocked": 0.0213,
"looking_up": 0,
"connecting": 0,
"tls_handshaking": 0,
"sending": 0.0238,
"waiting": 92.5957,
"receiving": -11.1397
},
"tls_version": "",
"tls_cipher_suite": "",
"ocsp": {
"produced_at": 0,
"this_update": 0,
"next_update": 0,
"revoked_at": 0,
"revocation_reason": "",
"status": ""
},
"error": "",
"error_code": 0,
"request": {
"method": "GET",
"url": "http://pong/ping/k6",
"headers": {
"User-Agent": [
"k6/0.30.0 (https://k6.io/)"
]
},
"body": "",
"cookies": {}
}
}
{
"remote_ip": "172.19.0.2",
"remote_port": 80,
"url": "http://pong/ping/k6",
"status": 200,
"status_text": "200 OK",
"proto": "HTTP/1.1",
"headers": {
"Content-Type": "application/json; charset=UTF-8",
"Date": "Fri, 26 Feb 2021 09:15:11 GMT",
"Content-Length": "13"
},
"cookies": {},
"body": "{\"pong\":\"k6\"}",
"timings": {
"duration": 42.0096,
"blocked": 0.0238,
"looking_up": 0,
"connecting": 0,
"tls_handshaking": 0,
"sending": 0.0381,
"waiting": 69.6788,
"receiving": -27.7073
},
"tls_version": "",
"tls_cipher_suite": "",
"ocsp": {
"produced_at": 0,
"this_update": 0,
"next_update": 0,
"revoked_at": 0,
"revocation_reason": "",
"status": ""
},
"error": "",
"error_code": 0,
"request": {
"method": "GET",
"url": "http://pong/ping/k6",
"headers": {
"User-Agent": [
"k6/0.30.0 (https://k6.io/)"
]
},
"body": "",
"cookies": {}
}
}
{
"remote_ip": "172.19.0.2",
"remote_port": 80,
"url": "http://pong/ping/k6",
"status": 200,
"status_text": "200 OK",
"proto": "HTTP/1.1",
"headers": {
"Date": "Fri, 26 Feb 2021 09:15:11 GMT",
"Content-Length": "13",
"Content-Type": "application/json; charset=UTF-8"
},
"cookies": {},
"body": "{\"pong\":\"k6\"}",
"timings": {
"duration": 88.9084,
"blocked": 0.0242,
"looking_up": 0,
"connecting": 0,
"tls_handshaking": 0,
"sending": 0.0232,
"waiting": 105.644,
"receiving": -16.7588
},
"tls_version": "",
"tls_cipher_suite": "",
"ocsp": {
"produced_at": 0,
"this_update": 0,
"next_update": 0,
"revoked_at": 0,
"revocation_reason": "",
"status": ""
},
"error": "",
"error_code": 0,
"request": {
"method": "GET",
"url": "http://pong/ping/k6",
"headers": {
"User-Agent": [
"k6/0.30.0 (https://k6.io/)"
]
},
"body": "",
"cookies": {}
}
}
{
"remote_ip": "172.19.0.2",
"remote_port": 80,
"url": "http://pong/ping/k6",
"status": 200,
"status_text": "200 OK",
"proto": "HTTP/1.1",
"headers": {
"Content-Type": "application/json; charset=UTF-8",
"Date": "Fri, 26 Feb 2021 09:15:41 GMT",
"Content-Length": "13"
},
"cookies": {},
"body": "{\"pong\":\"k6\"}",
"timings": {
"duration": 163.3468,
"blocked": 0.0295,
"looking_up": 0,
"connecting": 0,
"tls_handshaking": 0,
"sending": 0.0296,
"waiting": 196.8227,
"receiving": -33.5055
},
"tls_version": "",
"tls_cipher_suite": "",
"ocsp": {
"produced_at": 0,
"this_update": 0,
"next_update": 0,
"revoked_at": 0,
"revocation_reason": "",
"status": ""
},
"error": "",
"error_code": 0,
"request": {
"method": "GET",
"url": "http://pong/ping/k6",
"headers": {
"User-Agent": [
"k6/0.30.0 (https://k6.io/)"
]
},
"body": "",
"cookies": {}
}
}
{
"remote_ip": "172.19.0.2",
"remote_port": 80,
"url": "http://pong/ping/k6",
"status": 200,
"status_text": "200 OK",
"proto": "HTTP/1.1",
"headers": {
"Date": "Fri, 26 Feb 2021 09:15:41 GMT",
"Content-Length": "13",
"Content-Type": "application/json; charset=UTF-8"
},
"cookies": {},
"body": "{\"pong\":\"k6\"}",
"timings": {
"duration": 162.9286,
"blocked": 0.0286,
"looking_up": 0,
"connecting": 0,
"tls_handshaking": 0,
"sending": 0.0265,
"waiting": 167.0958,
"receiving": -4.1937
},
"tls_version": "",
"tls_cipher_suite": "",
"ocsp": {
"produced_at": 0,
"this_update": 0,
"next_update": 0,
"revoked_at": 0,
"revocation_reason": "",
"status": ""
},
"error": "",
"error_code": 0,
"request": {
"method": "GET",
"url": "http://pong/ping/k6",
"headers": {
"User-Agent": [
"k6/0.30.0 (https://k6.io/)"
]
},
"body": "",
"cookies": {}
}
}
{
"remote_ip": "172.19.0.2",
"remote_port": 80,
"url": "http://pong/ping/k6",
"status": 200,
"status_text": "200 OK",
"proto": "HTTP/1.1",
"headers": {
"Content-Type": "application/json; charset=UTF-8",
"Date": "Fri, 26 Feb 2021 09:15:41 GMT",
"Content-Length": "13"
},
"cookies": {},
"body": "{\"pong\":\"k6\"}",
"timings": {
"duration": 191.153,
"blocked": 0.0336,
"looking_up": 0,
"connecting": 0,
"tls_handshaking": 0,
"sending": 0.0626,
"waiting": 199.7006,
"receiving": -8.6102
},
"tls_version": "",
"tls_cipher_suite": "",
"ocsp": {
"produced_at": 0,
"this_update": 0,
"next_update": 0,
"revoked_at": 0,
"revocation_reason": "",
"status": ""
},
"error": "",
"error_code": 0,
"request": {
"method": "GET",
"url": "http://pong/ping/k6",
"headers": {
"User-Agent": [
"k6/0.30.0 (https://k6.io/)"
]
},
"body": "",
"cookies": {}
}
}
{
"remote_ip": "172.19.0.2",
"remote_port": 80,
"url": "http://pong/ping/k6",
"status": 200,
"status_text": "200 OK",
"proto": "HTTP/1.1",
"headers": {
"Content-Type": "application/json; charset=UTF-8",
"Date": "Fri, 26 Feb 2021 09:16:11 GMT",
"Content-Length": "13"
},
"cookies": {},
"body": "{\"pong\":\"k6\"}",
"timings": {
"duration": 25.157,
"blocked": 0.0935,
"looking_up": 0,
"connecting": 0,
"tls_handshaking": 0,
"sending": 0.0287,
"waiting": 28.694,
"receiving": -3.5657
},
"tls_version": "",
"tls_cipher_suite": "",
"ocsp": {
"produced_at": 0,
"this_update": 0,
"next_update": 0,
"revoked_at": 0,
"revocation_reason": "",
"status": ""
},
"error": "",
"error_code": 0,
"request": {
"method": "GET",
"url": "http://pong/ping/k6",
"headers": {
"User-Agent": [
"k6/0.30.0 (https://k6.io/)"
]
},
"body": "",
"cookies": {}
}
}
{
"remote_ip": "172.19.0.2",
"remote_port": 80,
"url": "http://pong/ping/k6",
"status": 200,
"status_text": "200 OK",
"proto": "HTTP/1.1",
"headers": {
"Date": "Fri, 26 Feb 2021 09:16:11 GMT",
"Content-Length": "13",
"Content-Type": "application/json; charset=UTF-8"
},
"cookies": {},
"body": "{\"pong\":\"k6\"}",
"timings": {
"duration": 53.5901,
"blocked": 0.0294,
"looking_up": 0,
"connecting": 0,
"tls_handshaking": 0,
"sending": 0.0312,
"waiting": 58.0011,
"receiving": -4.4422
},
"tls_version": "",
"tls_cipher_suite": "",
"ocsp": {
"produced_at": 0,
"this_update": 0,
"next_update": 0,
"revoked_at": 0,
"revocation_reason": "",
"status": ""
},
"error": "",
"error_code": 0,
"request": {
"method": "GET",
"url": "http://pong/ping/k6",
"headers": {
"User-Agent": [
"k6/0.30.0 (https://k6.io/)"
]
},
"body": "",
"cookies": {}
}
}
For context, here are some similar issues we've had in the past: https://github.com/loadimpact/k6/issues/588, https://github.com/loadimpact/k6/pull/862. This time it seems like:
- it's not an HTTP/2 issue, see
"proto": "HTTP/1.1"everywhere - we're reusing connections (
"connecting": 0in all cases) - requests were successful, they weren't cancelled or timed out or anything bad - we got a good response
I may be wrong, but this time it's looking like it might be a bug or a race in the Go stdlib's net/http/httptrace module... On the k6 side, receiving is calculated here: https://github.com/loadimpact/k6/blob/51790fc8df37113ac20b586b28051e21672dab16/lib/netext/httpext/tracer.go#L326-L328
It is the difference between done and gotFirstResponseByte. We get gotFirstResponseByte directly from the net/http/httptrace.ClientTrace hook, which is supposedly "called when the first byte of the response headers is available" (from the official docs: https://github.com/loadimpact/k6/blob/51790fc8df37113ac20b586b28051e21672dab16/lib/netext/httpext/tracer.go#L259-L265
done is calculated by the time we've already gotten a response, i.e. the whole RoundTrip() method is complete!
https://github.com/loadimpact/k6/blob/51790fc8df37113ac20b586b28051e21672dab16/lib/netext/httpext/request.go#L323
https://github.com/loadimpact/k6/blob/51790fc8df37113ac20b586b28051e21672dab16/lib/netext/httpext/transport.go#L201
https://github.com/loadimpact/k6/blob/51790fc8df37113ac20b586b28051e21672dab16/lib/netext/httpext/transport.go#L90-L91
https://github.com/loadimpact/k6/blob/51790fc8df37113ac20b586b28051e21672dab16/lib/netext/httpext/tracer.go#L267-L269
So, either I'm missing something major, or, somehow, httptrace.GotFirstResponseByte() gets called by Go's HTTP code after the whole HTTP request has already completed :confused:
On the other hand, it doesn't look like the relevant code from the Go stdlib does anything strange, or indeed, has been changed recently :confused: https://github.com/golang/go/blame/520f3b72db7befab2028d9a47376267cf2d274a9/src/net/http/transport.go#L2265-L2270
@na-- so far I did NOT manage to reproduce the issue on Linux host host info
CPU: Intel(R) Pentium(R) CPU J4205 @ 1.50GHz
CPU(s): 4
Thread(s) per core: 1
CPU max MHz: 2600.0000
CPU min MHz: 800.0000
RAM 4Gb Ubuntu 20.04.2 LTS kernel 5.4.0-66-generic Docker version 19.03.11, build 42e35e61f3
I'm officially stumped :sweat_smile: Debugging this would be super difficult when I can't reproduce it locally, and when it happens so rarely. See the check count in https://github.com/loadimpact/k6/issues/1872#issuecomment-786519330
✗ is http_req_receiving >= 0
↳ 99% — ✓ 1055782 / ✗ 8
It has happened 8 times out of 1055790 requests, i.e. in ~0.000758% of requests. It's probably some strange and very infrequent data race, and I imagine it happens even more rarely when you're not testing localhost, as is essentially the case with the docker-compose example, but real-world systems with higher latencies... If anyone has any ideas how we can track this down, please share. The quick "fix" would be to just replace this code: https://github.com/loadimpact/k6/blob/51790fc8df37113ac20b586b28051e21672dab16/lib/netext/httpext/tracer.go#L326-L328
With something like this:
if gotFirstResponseByte != 0 && done.After(gotFirstResponseByte) {
trail.Receiving = done.Sub(time.Unix(0, gotFirstResponseByte))
}
And we won't get any more negative http_req_receiving values, but without knowing the root cause, that may just mask the issue instead of actually fixing it. Who knows, it may be a valid fix/workaround, if the bug is that the stdlib is firing GotFirstResponseByte() too late, for some reason, but I won't be willing to bet that's the case :man_shrugging:
Hi @na-- One possibility is that the thread doing the latency measurement is migrated to another cpu between measurements.
monotonic clocks are guaranteed to increase on each cpu locally. However, there are cases where the clock between cpus is not synchronised. Most cpus will support invariant_tsc , but it is possible that multisocket machines don't synchronise across sockets. VMs/hypervisors also may not use tsc and/or may not expose tsc to a guest.
Ideas to reproduce:
runs tests on a machine/vm without tsc invariant clocksource taskset k6 to 2 cpus on difference sockets to encourage threads to migrate between sockets. simplify to a golang reproducer without any k6 or network code
Ideas to detect:
trace thread cpu migration events (typically via perf or ebpf on linux if it can be reproduced there)
Thanks, @alexb-img, this sounds like a very plausible explanation for what we observed! I can't test it right now, but assuming you are right, do you have any suggestions for a better fix purely in user-space Go, without any messing with eBPF and such?
The simplest "fix" might indeed be to just consider any negative values close to 0 to be just 0... :thinking:
Hey @ludenus, https://github.com/ludenus/k6-issue-1872/blob/f02a3f383a0fbc077ded73bb8d67af0273f40017/docker-compose.yaml#L12C4-L12C34 can you try to run an updated version of your docker-compose, please? k6 is now v0.51 and loadimpact image is not supported anymore.
You should use the following docker image:
grafana/k6:0.51.0
@ludenus what is your running OS? Is it Windows?
I tried to run it on Linux and I'm not yet able to reproduce it. As the comment in the code mentions, the reason could related to cancel requests. I don't think we have this case covered in our unit tests. It would be good to check and cover it.
