Learn F5 Technologies, Get Answers & Share Community Solutions Join DevCentral

Filter by:
  • Solution
  • Technology
Answers

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

Hi. I have an irule that calculates total response time, server response time and server connection time for each requests and logs the data with high speed logging. But sometimes the connection time is graether than the total response time, and I can't figure out how can this happend. I'm using an http profile without oneconnect. Any help will be appreciated.

This is the irule code:

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"
}

Thanks!!

1
Rate this Question

Answers to this Question

placeholder+image
USER ACCEPTED ANSWER & F5 ACCEPTED ANSWER

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.
0
placeholder+image
USER ACCEPTED ANSWER & F5 ACCEPTED ANSWER

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!!

0
placeholder+image
USER ACCEPTED ANSWER & F5 ACCEPTED ANSWER

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.

0
placeholder+image
USER ACCEPTED ANSWER & F5 ACCEPTED ANSWER

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!

0
placeholder+image
USER ACCEPTED ANSWER & F5 ACCEPTED ANSWER

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.

0