k6 https://k6.io/ tool reports negative http_req_duration time

Question

I am trying to run very simple scenario with k6 tool. Sometimes it reports negative number for http_req_duration time which is confusing me.

QUESTION: How is that possible or how to interpret negative number in this context?

The description of http_req_duration metric in official doc says

http_req_duration - Total time for the request. It's equal to http_req_sending + http_req_waiting + http_req_receiving (i.e. how long did the remote server take to process the request and respond, without the initial DNS lookup/connection times). float

My test script looks like this:

script.js

import { check } from 'k6';

export let options = {
  thresholds: {
    http_req_duration: ['avg < 200', 'p(99)<1000', 'p(99.999)<1000'], 
  },
};

export default function () {
  var res = http.get('http://pong/ping/k6');
  check(res, {
    'is status 200': (r) => r.status === 200,
    'is duration <= 1000ms': (r) => r.http_req_duration < 1000
  });
}

docker-compose.yaml

---
version: "3"
services:
  pong:
    image: "ludenus/pong:0.0.1"
    ports:
    - "8100:80"
    environment:
      PONG_LISTENING_ADDRESS: ":80"
  
  k6:
    image: "loadimpact/k6:0.30.0"
    volumes: 
      - ./script.js:/script.js
    command: run /script.js --vus 2000 --duration 10s
    depends_on: 
      - pong

k6_1    |      checks.....................: 0.00%  ✓ 0     ✗ 133631
k6_1    |      data_received..............: 18 MB  1.8 MB/s
k6_1    |      data_sent..................: 10 MB  1.0 MB/s
k6_1    |      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 
k6_1    |      http_req_connecting........: avg=3.96µs   min=0s         med=0s      max=34.35ms  p(90)=0s      p(95)=0s     
k6_1    |    ✓ http_req_duration..........: avg=14.05ms  min=-15.7758ms med=11.71ms max=163.09ms p(90)=27.25ms p(95)=33.93ms
k6_1    |      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
k6_1    |      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 
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.89ms  min=0s         med=11.56ms max=163.01ms p(90)=27.02ms p(95)=33.66ms
k6_1    |      http_reqs..................: 133631 13350.537278/s
k6_1    |      iteration_duration.........: avg=14.9ms   min=287.4µs    med=12.32ms max=227.44ms p(90)=28.72ms p(95)=35.79ms
k6_1    |      iterations.................: 133631 13350.537278/s
k6_1    |      vus........................: 200    min=200 max=200 
k6_1    |      vus_max....................: 200    min=200 max=200 

Answer 1

this seems like a minor bug in k6. I've created an issue about it: https://github.com/loadimpact/k6/issues/1872

As I mentioned in the issue, this is likely a case where the server starts responding before we have completely sent it the whole request. Can you please share any relevant details that would help us reproduce the problem in the GitHub issue, e.g. what server and app are you testing, OS and networking details, etc.