Forum Discussion

Jason_Heath_432's avatar
Jason_Heath_432
Icon for Nimbostratus rankNimbostratus
May 06, 2011

Is microsecond precision available in an iRule?

I am trying to get to microsecond precision in an iRule I am working on.

 

 

 

Based on reading the Tcl docs that I found a link to on this site (http://tmml.sourceforge.net/doc/tcl/index.html) I would expect "clock microseconds" to have worked. A bit more digging and experimentation after I got an error I would have expected "clock clicks -microseconds" to have worked. After that also triggered an error I started digging through the forums. At this point I'm not sure that microsecond precision is available but I haven't been able to find definitive documentation saying that. I tried to figure out the level of Tcl support that I should expect but have been unable to do so. I'm reasonably certain that I'm on a BigIP 6900 at version 10.2.1.

 

 

 

What I'm ultimately trying to achieve is an iRule that inserts a header named "X-Request-Start" that inserts a value like "t=1304697000869668". The following is what I have right now. There is a bit of debugging/development cruft in this version.

 

 

 

when HTTP_REQUEST {

 

set now t=[clock clicks]

 

set x_request_start "X-Request-Start"

 

set big_ip_x_request_start "BigIP-X-Request-Start"

 

 

HTTP::header remove $x_request_start

 

HTTP::header remove $big_ip_x_request_start

 

 

HTTP::header insert $x_request_start $now

 

HTTP::header insert $big_ip_x_request_start $now

 

HTTP::header insert X-HELLO there

 

}

 

 

 

Trimming that down to a focused version of what I'm really after one would get something like

 

 

 

when HTTP_REQUEST {

 

set now t=[clock microseconds]

 

set x_request_start "X-Request-Start"

 

HTTP::header remove $x_request_start

 

HTTP::header insert $x_request_start $now

 

}

 

 

 

The Tcl documentation for "clock clicks" states that without "If no -option argument is supplied, returns a high-resolution time value as a system-dependent integer value." I tried that hoping to get microseconds, I instead got a negative value that won't be useful to me.

 

 

this value came from an intermediate Apache server that inserted the sort of value I'm trying to achieve

 

t=1304702175756372

 

 

 

this value from "HTTP::header insert $big_ip_x_request_start $now" above

 

t=-1510467564

 

 

 

Can anyone explain what clicks means within an iRule? If I can't get to microseconds, can I get to milliseconds? I tried both "clicks -milliseconds" and "clock milliseconds" and go results that mirrored what I've seen attempting to get microseconds so I don't think milliseconds is available either.

 

application delivery
dev
devops
iRules
  • hooleylist's avatar
    hooleylist
    Icon for Cirrostratus rankCirrostratus
    May 06, 2011
    microsecond resolution isn't currently possible, but millisecond resolution should work fine for calculating deltas in time: 

    
set start_time [clock clicks -milliseconds]
 do something else
log local0. "delta: [expr {[clock clicks -milliseconds] - $start_time}]"

    http://www.tcl.tk/man/tcl8.4/TclCmd/clock.htmM5

    clock clicks ?-milliseconds? ... This value should only be used for the relative measurement of elapsed time.

    For the current time, I think the best you can get is second resolution.

    Aaron
  • hooleylist's avatar
    hooleylist
    Icon for Cirrostratus rankCirrostratus
    May 06, 2011
    I found an older post which said that microseconds support isn't possible until TCL v8.5. I think there are plans to update the TCL base in iRules from 8.4, but I don't know of any concrete timing for this.

     

     

    You could open a case with F5 Support and ask them to open a request for enhancement to support millisecond clock resolution in iRules. If you do, can you reply back with the RFE ID?

     

     

    Thanks, Aaron
  • Ed_Hammond_2611's avatar
    Ed_Hammond_2611
    Icon for Nimbostratus rankNimbostratus
    May 07, 2011
    If you use [clock clicks] you get the highest resolution timer value available on the platform with the least overhead possible. Of course that does not represent microseconds, but it can be very useful.
  • Jason_Heath_432's avatar
    Jason_Heath_432
    Icon for Nimbostratus rankNimbostratus
    May 12, 2011
    hoolio: Have you tried that within an iRule? I'm reasonably sure that I tried that Friday when I was working on this and I don't think the -milliseconds worked either.

     

     

    And does anybody know what value it is that clock clicks is returning?

     

  • spark_86682's avatar
    spark_86682
    Historic F5 Account
    May 12, 2011
    On my 10.1.0 box, "clock clicks" returns microseconds. Here's an example: 
         set a1 [clock clicks]
     set b1 [clock clicks -milliseconds]
     after 10
     set a2 [clock clicks]
     set b2 [clock clicks -milliseconds]
     after 100
     set a3 [clock clicks]
     set b3 [clock clicks -milliseconds]
     after 1000
     set a4 [clock clicks]
     set b4 [clock clicks -milliseconds]
     log local0. "As: $a1 $a2 $a3 $a4"
     log local0. "Bs: $b1 $b2 $b3 $b4"
     log local0. "a2-a1: [expr $a2 - $a1]  a3-a2: [expr $a3 - $a2]  a4-a3: [expr $a4 - $a3]"
     log local0. "b2-b1: [expr $b2 - $b1]  b3-b2: [expr $b3 - $b2]  b4-b3: [expr $b4 - $b3]"
    and here's what it logs: 
     As: -1076552924 -1076543381 -1076442893 -1075443255
 Bs: -426278316 -426278306 -426278206 -426277206
 a2-a1: 9543  a3-a2: 100488  a4-a3: 999638
 b2-b1: 10  b3-b2: 100  b4-b3: 1000
    The microseconds counts each round to the number of milliseconds that we waited, and that were measured.

    The negative numbers are because Tcl is presenting unsigned numbers as signed numbers, but the subtraction math still works out, so don't be fooled by that. However, this also means you won't be able to measure durations of more than 2^31 microseconds, which is about 35 minutes.
  • Colin_Walker_12's avatar
    Colin_Walker_12
    Historic F5 Account
    May 17, 2011
    Very nice info, thanks Spark. I seem to remember some gotchas regarding trying to get to this level of detail with the clock command, but can't seem to turn up the thread I'm thinking of right now. Anything we should watch out for here? If I find what I'm thinking of I'll post it here.

     

     

    Colin
  • Ed_Hammond_2611's avatar
    Ed_Hammond_2611
    Icon for Nimbostratus rankNimbostratus
    Jul 24, 2011
    The clock clicks number is not equal to actual microseconds. You need to take into account the processor frequency, and there may be some inaccuracy due to interrupts, etc. In general, I tell people they can think of it as microseconds but the greater the number (difference between first observation and second observation) the greater the skew from accuracy. Imperical testing over a long period using an external time source (known to be accurate) will help prove the case.

     

     

    Write an irule that just does an "HTTP::respond 200 content [clock clicks]" and call it every 60 seconds for several days. You'll see the skew for the box in question. When you have an HA pair, you can't assume the processor frequencies are identical either. So you need to check both boxes.