Don't understand where response time come from when debugging

[matidmarino]

I am debugging an artillery test and I've found some issues that I can't figure out.

Having this script:

{
   "config": {
      "target": "https://test_account-persistence-benchmark.io",
      "phases": [
         {
            "duration": 2,
            "arrivalRate": 1,
            "name": "Warm up"
         }
      ],
      "defaults": {
      },
      "payload": {
         "path": "gets.csv",
         "fields": [
            "account_id",
            "reserve_id",
         ]
      }
   },
   "scenarios": [
      {
         "name": "Look for account id",
         "flow": [
            {
               "get": {
                  "url": "/balance/{{ account_id }}"
               }
            }
         ]
      },
      {
         "name": "Look for reserve id",
         "flow": [
            {
               "get": {
                  "url": "/reserve/{{ reserve_id }}"
               }
            }
         ]
      }
   ]
}

I'm running DEBUG=http:request,http:response artillery run arti-gets.json >& debug_arti.txt

The result in debug_arti.txt file is (request id and response in bold):

Phase started: Warm up (index: 0, duration: 2s) 11:09:14(-0300)

2022-01-25T14:09:15.791Z http:request request start: /reserve/2944701248 [---> Request 1]
Phase completed: Warm up (index: 0, duration: 2s) 11:09:16(-0300)

2022-01-25T14:09:16.776Z http:request request start: /balance/464365440 [---> Request 2]
2022-01-25T14:09:17.006Z http:response {
"date": "Tue, 25 Jan 2022 14:09:17 GMT",
"content-type": "application/json; charset=utf-8",
"content-length": "514",
"connection": "keep-alive",
}
2022-01-25T14:09:17.006Z http:response "{"id":2944701248,"user_id":468103481} [---> Response 1]

2022-01-25T14:09:17.545Z http:response {
"date": "Tue, 25 Jan 2022 14:09:17 GMT",
"content-type": "application/json; charset=utf-8",
"content-length": "593",
"connection": "keep-alive",
}
2022-01-25T14:09:17.545Z http:response "{"ID":464365440,"UserID":799309860}" [---> Response 2]

---

Summary report @ 11:09:17(-0300)

vusers.created_by_name.Look for reserve id: .................................... 1
vusers.created.total: .......................................................... 2
vusers.created_by_name.Look for account id: .................................... 1
vusers.completed: .............................................................. 2
vusers.session_length:
min: ......................................................................... 775.1
max: ......................................................................... 1236.3
median: ...................................................................... 772.9
p95: ......................................................................... 772.9
p99: ......................................................................... 772.9
http.request_rate: ............................................................. 2/sec
http.requests: ................................................................. 2
http.codes.200: ................................................................ 2
http.responses: ................................................................ 2
http.response_time:
min: ......................................................................... 260
max: ......................................................................... 383
median: ...................................................................... 262.5
p95: ......................................................................... 262.5
p99: ......................................................................... 262.5

I don't understand where the response time in the summary come from. If we look the debug file the first request is at time 14:09:15.791Z and the response is at 14:09:17.006Z (215ms). The second request is at time 14:09:16.776Z and the response is at 14:09:17.545Z (769ms). These numbers don't match with vusers sesion length either. Additionally, I can't understand which is the calculation for the median as it should be a value from the dataset.

Thanks.

[hassy]

hi @matidmarino 👋

Timestamps in debug messages don't necessarily correspond to the timestamps which are recorded for the metric output. For example, http.response_time metric is based on TTFB, whereas with debug mode enabled, Artillery's HTTP engine will wait for the whole response to arrive before printing response details. That would explain why http.response_time.min=260 in the report, but the difference between timestamps in debug output is 14:09:17.006Z - 14:09:15.791Z = 209+1000+6 = 1215ms.

As to values of median (and p99 + p95) -- the dataset is simply too small for meaningful values to be produced. We use DDSketch for tracking histogram & calculating percentiles, and that's the approximated values it produces. If you want to know more about why that doesn't work well for small datasets, this is one good place to start: https://www.reddit.com/r/statistics/comments/10w5nj/calculating_the_95th_percentile_of_a_small_data/

[matidmarino]

Sorry to bother again. Can I get from artillery api the distribution of all latency values? (so that i can calculate the mean on my own in a plugin for example)

[hassy]

@matidmarino yep, afterResponse hooks have access to the latency of a request via response.timings.phases.firstByte. You can attach those to every request in your scenario like this:

  - post:
      url: "/some/route"
      afterResponse: "myCustomFunction"

or in a plugin, like here:

https://github.com/artilleryio/artillery-plugin-metrics-by-endpoint/blob/master/index.js#L14-L40

There's no easy way to buffer all of those values in-memory until the end of the test right now and write them to a file just once at the end, but you should be able to console.log them and grab them from the output with a bit of grep :)

[matidmarino]

Thanks!

Last one, I promess. How does artilllery know which response belongs to which request?

[hassy]

No worries 😄 The afterResponse hook is called with a request object for which it's being invoked, so you can access the URL, request headers etc. Is that what you meant?

[matidmarino]

No, I mean when calculating the latency. The responses to several consecutive requests could arrive unordered so I don't understand how you match requests to responses in order to calculate de TTFB.