Response Time Difference

Hi there,

I have a dependency to log the response time for each request during the whole test. So, I have record the timestamp before and after the request has been executed. However, I observed some differences between the gatling report and logged values.
This is the gatling result for my test:

================================================================================
---- Global Information --------------------------------------------------------
> request count                                    1468243 (OK=1414263 KO=53980 )
> min response time                                     23 (OK=23     KO=23    )
> max response time                                   3080 (OK=3080   KO=2384  )
> mean response time                                    67 (OK=67     KO=47    )
> std deviation                                        131 (OK=132    KO=85    )
> response time 50th percentile                         38 (OK=38     KO=33    )
> response time 75th percentile                         51 (OK=51     KO=41    )
> response time 95th percentile                        157 (OK=162    KO=74    )
> response time 99th percentile                        767 (OK=774    KO=380   )
> mean requests/sec                                2447.072 (OK=2357.105 KO=89.967)

But in my log file, when I checked for the number of records greater than 767 milliseconds, it was 1233265 requests(which is around 80% of total requests).

Below is the snippet of the log file:
2024-01-01T09:56:42Z,1704103003875,998
2024-01-01T09:56:42Z,1704103003875,981
2024-01-01T09:56:42Z,1704103003875,971
2024-01-01T09:56:42Z,1704103003876,974
2024-01-01T09:56:42Z,1704103003876,967
2024-01-01T09:56:42Z,1704103003876,982
2024-01-01T09:56:42Z,1704103003876,972
2024-01-01T09:56:42Z,1704103003876,978
2024-01-01T09:56:42Z,1704103003877,985
2024-01-01T09:56:42Z,1704103003877,986
2024-01-01T09:56:42Z,1704103003880,970
2024-01-01T09:56:42Z,1704103003881,988
2024-01-01T09:56:42Z,1704103003881,989
2024-01-01T09:56:42Z,1704103003882,987
2024-01-01T09:56:42Z,1704103003882,1004
2024-01-01T09:56:42Z,1704103003883,1010

Below is my code:

  def getUTCOffsetInMS: String = {
    val currentUTCTime: ZonedDateTime = ZonedDateTime.now(ZoneId.of("UTC"))
    currentUTCTime.toInstant.toEpochMilli.toString
  }
  def convertMillisecondsToDate(milliseconds: Long): String = {
    val dateFormat = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss'Z'")
    dateFormat.setTimeZone(TimeZone.getTimeZone("UTC"))
    val utcDate = new Date(milliseconds)
    dateFormat.format(utcDate)
  }

def logRequestForOldRec(req: HttpRequestBuilder, reqName: String, writer: FileOutputStream, isLogNeeded: Boolean = true): ChainBuilder ={
    doIfOrElse(isLogNeeded) {
      exec(session => {
        val startTime: Long = getUTCOffsetInMS.toLong
        session.setAll(Map("startTime" -> startTime))
      })
        .exec(req)
        .exec(session => {
          val currentUTCTimeMillis: Long = getUTCOffsetInMS.toLong
          val total = currentUTCTimeMillis - session("startTime").as[Long]
          val utcAbsTime = convertMillisecondsToDate(session("startTime").as[Long])
          val logStr = s"$utcAbsTime,$currentUTCTimeMillis,$total\n"
          writer.write(logStr.getBytes(), 0, logStr.length)
          session
        })
    }
    {
      exec(req)
    }
  }

Hi,

Your handmade time measurement introduces an overhead (long/string/bytes conversions, synchronized writer) and doesn’t measure as close to the request as we do.

Don’t try to roll your own thing.

Hi @slandelle, thanks for the information. I get what you are saying, but, other than the explicit time measurement I have done above, is there any way to get the information accurately? As I have the dependency to log the information for each request to further analyze our system.

Here we can only help with test crafting.

It looks like you’re trying to build something that overlaps with Gatling Enterprise, which is not something we can help with.

Regards

Gatling is using HTTP round trip which is counting time from the moment when VU makes the request until a response is returned.
Your definition of response time only starts when VU is connected, it lacks the very moment that VU is initiated.
.
Simply put, here is Gatling time counted (as I understand how HTTP round trip works):

VUs birthtime + VUs connecting + System processing time + VUs get response back

Your definition:

VUs connecting + System processing time + VUs get response back

I can’t help you on giving solutions, but you can try to look into Gatling docs to understand the tech underlying it and improve as you need.

@trinp your post is wrong.

Gatling time measurement = DNS resolution time + HTTP connect time + TLS handskahe time + HTTP response time

@Zuhair 's time measurement = Gatling time measurement + request building + response processing + writing on a synchronized writer under heavy load

2 Likes

Thank @slandelle for pointing out.

Thanks, @slandelle for the information.

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.