Not understanding metrics of k6

Question

I have load tested my server with k6 and I have some doubts about the results I have obtained.

          /\      |‾‾|  /‾‾/  /‾/   
     /\  /  \     |  |_/  /  / /    
    /  \/    \    |      |  /  ‾‾\  
   /          \   |  |‾\  \ | (_) | 
  / __________ \  |__|  \__\ \___/ .io

    init [----------------------------------------------------------] runner
    init [----------------------------------------------------------] options
    init [----------------------------------------------------------] executor
    init [----------------------------------------------------------]   engine
    init [----------------------------------------------------------]   collector
    init [----------------------------------------------------------]   server
  execution: local
     output: -
     script: ./src/benchmark/script.js

    duration: 20s, iterations: -
         vus: 1,   max: 1

    init [----------------------------------------------------------] starting
    ✓ status was 200

    checks.....................: 100.00% ✓ 477 ✗ 0  
    data_received..............: 9.5 GB  477 MB/s
    data_sent..................: 55 kB   2.8 kB/s
    http_req_blocked...........: avg=3.69µs  min=1.88µs  med=2.87µs  max=282.62µs p(90)=4.08µs  p(95)=4.33µs 
    http_req_connecting........: avg=485ns   min=0s      med=0s      max=232.2µs  p(90)=0s      p(95)=0s     
    http_req_duration..........: avg=18.87ms min=18.18ms med=18.86ms max=27.83ms  p(90)=19.35ms p(95)=19.44ms
    http_req_receiving.........: avg=36.37µs min=13.59µs med=23.64µs max=786.38µs p(90)=60.69µs p(95)=80.54µs
    http_req_sending...........: avg=39.7µs  min=13.82µs med=20.18µs max=3.16ms   p(90)=34.81µs p(95)=35.58µs
    http_req_tls_handshaking...: avg=0s      min=0s      med=0s      max=0s       p(90)=0s      p(95)=0s     
    http_req_waiting...........: avg=18.8ms  min=18.15ms med=18.82ms max=27.77ms  p(90)=19.26ms p(95)=19.31ms
    http_reqs..................: 478     23.899925/s
    iteration_duration.........: avg=41.83ms min=40.07ms med=41.51ms max=112.2ms  p(90)=42.18ms p(95)=42.66ms
    iterations.................: 477     23.849925/s
    vus........................: 1       min=1 max=1
    vus_max....................: 1       min=1 max=1

Considerations:

The size of the response is 20MB.
I have configured the test with only 1 Virtual User.
The client (a m5.4xlarge EC2 instance) makes these requests to server (another m5.4xlarge EC2 instance).
Both servers are in the same Availability Zone.
I have pinged my server and these were the results obtained:

150 packets transmitted, 150 received, 0% packet loss, time 152557ms
rtt min/avg/max/mdev = 0.162/0.220/0.293/0.031 ms

150 packets transmitted, 150 received, 0% packet loss, time 152569ms
rtt min/avg/max/mdev = 0.164/0.217/0.262/0.028 ms

150 packets transmitted, 150 received, 0% packet loss, time 152574ms
rtt min/avg/max/mdev = 0.162/0.218/0.426/0.037 ms

150 packets transmitted, 150 received, 0% packet loss, time 152567ms
rtt min/avg/max/mdev = 0.173/0.227/0.266/0.028 ms

The metrics I'm interested in are the following:

http_req_receiving.........: avg=36.37µs
http_req_sending...........: avg=39.7µs
http_req_waiting...........: avg=18.8ms
http_req_duration..........: avg=18.87ms
iteration_duration.........: avg=41.83ms

If k6 documentation says that:

http_req_sending: Time spent sending data to remote host.
http_req_receiving: Time spent receiving response data from remote host.

The avg ping was 0.220ms (220µs) and both http_req_receiving and http_req_sending are lower than avg ping.

The problem that I'm having is that I don't know how to relate ping with http_req_receiving and http_req_sending.

What I think is that http_req_sending is the time taken to a request travel from point A to point B, and http_req_receiving is the time taken to a request travel from point C to point D. Am I right?

Check the following image: https://i.ibb.co/m6JJDK1/Screen-Shot-2019-02-02-at-11-23-00.png

EDIT: I have tested with the curl that ... suggested. Here are the results from some curls:

For a response that contains 20 million characteres (20MB):

Connect: 0.000241 TTFB: 0.028431 Total time: 0.061042

Connect: 0.000254 TTFB: 0.018196 Total time: 0.050792

Connect: 0.000236 TTFB: 0.023359 Total time: 0.056002

Connect: 0.001865 TTFB: 0.019826 Total time: 0.053621

Connect: 0.000238 TTFB: 0.018920 Total time: 0.051638

Connect: 0.000240 TTFB: 0.018243 Total time: 0.050905

Connect: 0.000226 TTFB: 0.019197 Total time: 0.051828

Connect: 0.000226 TTFB: 0.018293 Total time: 0.050941

Connect: 0.000239 TTFB: 0.019187 Total time: 0.051830

For a response that contains 1 character (1 byte):

Connect: 0.000241 TTFB: 0.000539 Total time: 0.000562

Connect: 0.000238 TTFB: 0.000532 Total time: 0.000553

Connect: 0.000237 TTFB: 0.000525 Total time: 0.000547

Connect: 0.000257 TTFB: 0.000524 Total time: 0.000548

Connect: 0.000231 TTFB: 0.000499 Total time: 0.000519

Connect: 0.000238 TTFB: 0.000512 Total time: 0.000537

Connect: 0.000232 TTFB: 0.000511 Total time: 0.000534

It’s not possible to measure the time it takes for the data to get from one point to another. This is not a “ping,” it is a real world HTTP request and response. So, no, your description is not correct. The time you are talking about is the measure of time the testing computer spent actually reading or writing the data. With buffering, and the fact the two computers are on the same network, those two metrics are virtually useless. — Appleoddity, Feb 02 '19 at 17:59

score 0 · Answer 1 · answered Feb 04 '19 at 07:01

As it was already mentioned the metrics k6 provides are (mostly) for HTTP as a protocol and as such relating it to ping might be a bit ... tricky :).

Basically ping measures how long a single packet gets from point A to B and from C to D combined. It doesn't measure neither one of the paths alone. This is what is usually called a roundtrip. It is also important to note that ping doesn't use tcp which adds additional speedups/slowdowns when we have multitute of roundtrips as they are in the case of HTTP requests.

On the other hand k6 measures how much different parts of a whole HTTP request (multitude of those round trips) is taking. In particular http_req_sending is measuring the whole time from the moment k6 has acquired a connection to the host to the time it has written the request. Respectfully http_req_receiving is the whole time from the moment k6 received the first byte back to the moment it has received the last byte of the response. Neither one of them measures roundtrips really - in the case of sending the underlying OS might not actually send the data for some time and we might receive the whole response from the OS very fast.

For your particular numbers: http_req_sending looks pretty okay - it is small because it is mostly us writing some bytes to a connection and the OS saying that it will send the data. The interesting is your http_req_receiving which is also very small (consistently) as I would expect it would take quite a bit longer, with response of this size. There is either some very heavy buffering happening somewhere before k6 or your are using an old version of k6 (pre v0.23.1) where we had some bugs when HTTP2 was used. Or we have not fixed all the bugs in those cases :(.

You might want to test with curl to see how big the response times then will be

curl -o /dev/null -H 'Cache-Control: no-cache' -s -w "Connect: %{time_connect} TTFB: %{time_starttransfer} Total time: %{time_total} \n"

curl script from https://gist.github.com/sandeepraju/1f5fbdbdd89551ba7925abe2645f92b5

source: I am a k6 developer ;)

Hi @Михаил Стойков, sorry for the late reply. I have edited the question and added the results of the curl you have suggested. So, what we can conclude are two things: 1) http_req_duration metric that k6 provides is actually TTFB from the curl results; and 2) iteration_duration that k6 provides is actually the total time from the curl results. So, If that is the case, k6 documentation should be updated with this. I'll appreciate if you could confirm if my conclusions are correct. Thank you! — John, Feb 08 '19 at 22:59
@John 1. `http_req_duraton` should be what curl reports as `total time` 2. TTFB will be most equal to `http_req_waiting` + `http_req_connecting` + `http_req_blocked`(which usually is very small) 3. `iteration_duration` is the whole time from the begging of the call to the `default` function until it returns which because of JS VM takes a lot longer than the actual request but it includes everything in the `default` function. 4. The only problem I see is `http_req_receiving` — Михаил Стойков, Feb 14 '19 at 10:33
I should mention that k6 caches connection and support http2 out of the box which means that it connect time will drop to zero (which it does) after the first request k6 makes. You can disable connection reuse with cli flag `--no-connection-reuse` more info at `https://docs.k6.io/docs/options` this will probably show you numbers closer to curl — Михаил Стойков, Feb 14 '19 at 10:40

Not understanding metrics of k6

1 Answers1