Irule for getting total response time, server response time and server connection time

A few comments:

• If you look at the actual order of events (on a v11 system), it should flow like this:

  CLIENT_ACCEPTED
  HTTP_REQUEST
  LB_SELECTED
  SERVER_CONNECTED
  HTTP_REQUEST_SEND
  HTTP_RESPONSE
  HTTP_RESPONSE_RELEASE
  

Your connection_time measurement is taken from the current time at SERVER_CONNECTED minus the LB_SELECTED time, which should just be the time it took to establish the 3-way handshake with the server. Assuming the "total response time" you're referring to is the calculated upstream_time, then it is certainly possible that a server side 3-way handshake could take longer than the actual request/response to that server (unlikely but not impossible) as the two aren't really related. This is part of the charm of OneConnect.

• You won't get the same granularity, but the request logging profile will give you response size and response milliseconds (The elapsed time in milliseconds between receiving the request and sending the response) in an HSL logging profile without an iRule.

Hi Kevin.

 

First of all, thanks for the answer. But the total_time is not the upstream time. It is the time between the events HTTP_REQUEST and HTTP_RESPONSE_RELEASE. I understood that it is the time transcurred since the request came to de F5 until it responds to the client. The upstream time it the time between HTTP_REQUEST_SEND and HTTP_RESPONSE. The connection_time should be smaller than total_time, because the LB_SELECTED and SERVER_CONNECTED happend between HTTP_REQUEST and HTTP_RESPONSE_RELEASE. How can the connection_time be greather than the total_time?

 

Thanks!!

 

the total_time is not the upstream time. It is the time between the events HTTP_REQUEST and HTTP_RESPONSE_RELEASE

 

Right. Had to read that part again. I can definitely see where you're going with this, but let me offer up one theory. The CLIENT_ACCEPTED, LB_SELECTED, and SERVER_CONNECTED events are only going to be triggered ONCE per TCP session, while the HTTP events will potentially trigger multiple times within a single TCP session. You may notice that connection_time stays the same across multiple requests - an indication that it is probably being (statically) reused from the request that initiated the handshake. So it is then possible that the initial server side handshake could have taken longer than any subsequent HTTP request/response cycle - not the first one obviously, but one that happened after the first one but in the same TCP session.

 

Thanks!! It make sense what you said. So, I fixed the irule, putting "set connection_time 0" in the last part of the event HTTP_RESPONSE_RELEASE, so only when the SERVER_CONNECTED event happends, I calculate the connection_time, and that only happends once per connection, right?. This is the fixed irule:

when RULE_INIT  {
    set static::bigip [info hostname]
    set static::facility <191>
    set static::hsl_prefix "$static::facility|host=$static::bigip"
}

when CLIENT_ACCEPTED {
    set hsl [HSL::open -proto UDP -pool hsl_pool]
    set tcp_start_time [clock clicks -milliseconds]
}

when HTTP_REQUEST {
    set http_request_time [clock clicks -milliseconds]
}

when HTTP_REQUEST_SEND  {
    set http_request_send_time [clock clicks -milliseconds]
}

when LB_SELECTED  {
    set lb_selected_time [clock clicks -milliseconds]
        set hsl_prefix "${static::hsl_prefix}|upstream=[LB::server addr]"
}

when SERVER_CONNECTED  {
    set connection_time [expr {[clock clicks -milliseconds] - $lb_selected_time}]
}

when HTTP_RESPONSE  {
    set upstream_time [expr {[clock clicks -milliseconds] - $http_request_send_time}]
}

when HTTP_RESPONSE_RELEASE {
    HSL::send $hsl "$hsl_prefix|event=X_REQUEST|total_time [expr {[clock clicks -milliseconds] - $http_request_time}]|upstream_time $upstream_time|connection_time $connection_time|vserver_name [virtual name]\n"
    set connection_time 0
}

Thanks!

I've taken this concept and expanded it here:

 

https://devcentral.f5.com/codeshare/logging-irule-1180

 

This version logs millisecond timestamps, handles connections that close early, and uses a $log() array so other irules on the same vip can add fields to log. Logging request headers, response headers, country code, etc.