iRule execution time

You cannot really time the execution and you wouldn't want to log each execution of an iRule/event but the iRule stats (which use the iRule timing Only1masterblaster linked to above and is enabled by default in 11.5.0 and above) can be used to get CPU cycle data.

In TMSH run:

show ltm rule

You will get an output like the following

-----------------------------------------------------------------------------
Ltm::Rule Event: my_iRule
-----------------------------------------------------------------------------
Priority                 500
Executions
  Total                    12345
  Failures                 4
  Aborts                   1
CPU Cycles on Executing
  Average                  10987
  Maximum                  50543
  Minimum                  506

The CPU cycles are the number of CPU clicks that take place, I have a python script which take take a text file of iRule stats in the above format and output into a CSV file but need to find it and make sure fit to be shared. (If I can share it I will upload to a Code Snippet and post a link here).

The team I work with used these stats as part of an iRule optimization project. We cleared the stats and ran a set of traffic load and recorded the iRule stats at several mid points and the end of the traffic load. Running this several times updating iRules between each test we could work out if changes decreased or increase CPU load on the F5 devices.

NOTE: Only major points I have come across with this is:

1. Resetting iRule stats is a little hit and miss depending on the iRule and the version of TMOS you are running. Found often trying to reset stats after an iRule change and all or some of the stats fail to reset back to zero.
2. If you have an iRule with the same event, e.g. HTTP_REQUEST, running multiple times with different priorities the stats look to be a cumulative value of all of that event in the iRule. To fix either split your iRule events into different rules or accept and remove duplicate entries.

Finally I am looking into iRule LX as a possible method of tracking iRule utilization by making a call to start a timer a the start of an iRule then call to stop the timer at the end of the iRule, this is still in the planning (and learning Node.js) phase but if manage to sort will look to share in the future.

Have a look here: https://devcentral.f5.com/wiki/iRules.timing.ashx

Hi Shipszky,

beside of the build-in iRule option (click me), you could also measure the time needed to execute certain commands / code blocks by counting the cycles needed with a very simple syntax...

 Store the start time
set start_time [clock clicks]

 This is the command we would like to check.
set aes_key [AES::key 256]

 Store the stop time
set start_time [clock clicks]

 Log the calculated time taken
log local0.debug "Time Taken: [expr { $stop_time - $start_time }]"

The output of this simple ample is not as granular as the build-in timing option, but on the other hand much easier to use.

Note: Personally, I use the iRule below to develop my iRules and test the performance of individual commands and code blocks. The iRule has also a build in function to statisticaly calculate the time taken over multiple request...

https://devcentral.f5.com/codeshare/procedure-based-html-debug-page-with-elapsed-time-performance-data

Cheers, Kai