VERY confusing results from http_req_duration vs calculated response time

Grafana k6 OSS Support
1

hello, i’m seeing duration times from Response.timings.duration that are REALLY confusing. In the following script:

var date = new Date();
var startRequest = date.getMilliseconds();
const response = http.get(url, params);
var date = new Date();
var endRequest = date.getMilliseconds();
var totalTime = startRequest - endRequest;
console.info("Response times: calculated response time=" + totalTime + ", k6 response time=" + response.timings.duration)

I get the following result:

time="2021-05-16T21:36:41Z" level=info msg="Response times: calculated response time=175, k6 response time=824.0651" source=console

Why is my totalTime so much lower than response.timings.duration? Maybe I’m not understanding response.timings.duration??? Can someone please help me? It’s very confusing!!!

2

Hi @varena, welcome to the forum :tada:

getMilliseconds returns the milliseconds since the late second - what you will see if you print the date in some format and you print the milliseconds as well, not the milliseconds since 1970 which is probably what you wanted.

For the later you need to use getTime or even better Date.now().

Additionally timings.duration will always be smaller then what you measure and especially for a single first request it will be even smaller as it doesn’t include the connection and dns lookup times as explained here

Hope this clears things up for you :slight_smile:

3

thanks, @mstoykov ! that was very helpful. but i’m still a little confused by http_req_duration. in the attached results summary, the number of http_reqs is 2.553453/s so that’s about 392 ms. but http_req_duration reports the following metrics, which are no where near 392.

avg=1309.71ms min=1122.30ms med=1257.09ms max=2126.62ms p(90)=1475.56ms p(95)=1666.70ms

and when i execute the request in a bash script the response time is always around 400ms or less. why are the values for http_req_duration so high?

test-summary
test-summary910×261 50.4 KB

4

When you execute the request in your bash script, presumably you are just calling the endpoint once, whereas in the k6 test, you’re calling it with multiple VUs (threads) concurrently (2.5/sec on average). Doing so could obviously increase the response time, particularly if the server is single-threaded.

If you want to see the equivalent to what your bash script is doing, you should just run the k6 script with a single VU.

5

thanks, @Tom. in my bash script, i’m executing 5 concurrent curls. so for a duration of 30s, i execute 5 concurrent requests with a 500ms sleep. i get the following:

total requests=85
requests per second=2.8333
Average response time in milli: 251.0470

in my k6 script, i have 5 VUs with a duration of 30s. 154 requests were submitted for 4.682934/s. 1000ms divided 4.68 is an average of 214ms. but the following response times are reported. why is the average more than double 214ms.

http_req_duration..............: avg=499.90ms min=292.87ms med=454.03ms max=2045.70ms p(90)=744.82ms p(95)=839.49ms

i attached a screenshot of the full report.

Screen Shot 2021-05-17 at 3.25.53 PM
Screen Shot 2021-05-17 at 3.25.53 PM872×248 49.6 KB

6

Are you able to share the script? You can leave out the URL.

7

thanks, @tom. i can’t upload it because only image file extensions are allowed.
but here is the script:

import papaparse from 'https://jslib.k6.io/papaparse/5.1.1/index.js';
import { textSummary } from 'https://jslib.k6.io/k6-summary/0.0.1/index.js';
import { randomIntBetween } from "https://jslib.k6.io/k6-utils/1.1.0/index.js";
import { check, sleep } from 'k6';
import http from 'k6/http';
import { SharedArray } from 'k6/data'
import { authenticate } from './common/authenticate.js';

const host = JSON.parse(open('./data/host.json'));
const userName = JSON.parse(open('./user-name.json'));
const testData = new SharedArray('test data', function() {
    return papaparse.parse(open('./test-data.csv'), { header: true }).data;
});

const vus = 5;

export let options = {
    vus: vus,
    duration: '30s',
    summaryTimeUnit: 'ms',
};

export function setup() {
    const authResponse = authenticate();
    return authResponse;
}

export default function (data) {

    const callerIdParams = {
        headers: {
            'Content-Type': 'application/json',
            'Accept' : 'application/vnd.mobileheartbeat.banyan-v1.0+json',
            'Authorization' : 'Bearer ' +  data.jwtToken,
        },
    };

    const callerIdBaseUrl = 'http://' + host.contacts + '/contacts/caller-id-aggregate/unsorted';

    const testDataRow = testData[randomIntBetween(1, 20000)];
    const phoneNumber = testDataRow.phoneNumber;
    const facilityId = testDataRow.facilityId;
    const displayName = userName.displayName;

    const callerIdUrl = callerIdBaseUrl + '?phoneNumber=' + phoneNumber + '&facilityId=' + facilityId;
    const callerIdResponse = http.get(callerIdUrl, callerIdParams);

    const contactData = callerIdResponse.json();
    const id = contactData.data.id;
    console.debug(`Caller ID: id=${id}, displayName=${displayName}, VU=${__VU}, ITER=${__ITER}`);

    check(callerIdResponse, {
        "is status 200": (r) => r.status === 200
    });

    sleep(.5)
}


export function handleSummary(data) {
    console.log('Preparing the end-of-test summary...');
    return {
        'stdout': textSummary(data, { indent: ' ', enableColors: true}),
    }
}
8

Sorry - by share I meant paste :slight_smile:

The iteration duration will include the .5 seconds spent sleeping (sleep(.5)), so that’s why iteration_duration averaged 1001.7ms yet the average response time was 499.90ms.

Not sure that particular division makes any sense anyway. The 4.68/s is the request rate. Why curl’s requests/sec is lower despite the lower average response time is odd. I’d need to see the curl command you’re running to try and figure that out.

The k6 output suggests that there is a rather lengthy delay for Time-To-First-Byte (TTFB), which is what http_req_waiting represents. With the options you’ve got, k6 will start all 5 VUs at the same time. Could your curl command be staggering when the requests are made? That might explain why we are reporting higher response times.

What do you see if you run just a single VU with k6, and likewise just a single thread with curl? I would expect the output to be very similar.

9

thanks, @Tom. I think I figured out the issue. the authentication request in the setup is included in http_req_duration. when i commented out the setup function and hardcoded the JWT in the headers, http_req_duration was closer to what i get in my bash script.

is there anyway to igore http calls made in the setup? i found this online: Ignore http calls made in Setup or Teardown in results? - #2 by nedyalko