Procedure based HTML Debug-Page with elapsed time performance data

Problem this snippet solves:

The outlined iRule contains a debugging procedure that can become an useful tool while developing HTTP related iRules.

The debug

[proc]

can be plugged into existing iRules on a position of your choice, to break the iRule execution, collect various informations and display them in a easy to use HTML page. The debug

[proc]

is also able to meassure the elapsed time between independent code positions to get a first impression which coding technique performs better than the other.

The debug

[proc]

will store the collected performance data of every single execution in a scaling window session

[table]

for statistical calculation. It would output statistical information in a raw format and a #% cuttoff style to filter outliers.

Cheers, Kai

How to use this snippet:

Procedure functionality

To store debugging information use..

set debug(ORIG_HOST) "somedata [HTTP::host] [HTTP::uri]"

To meassure elapsed time between a given starting/ending point...

set time(YOUR_TIMER_NAME1) [clock clicks]
... your code... 
lappend time(YOUR_TIMER_NAME1) [clock clicks]

set time(YOUR_TIMER_NAME2) [clock clicks]
... your code... 
lappend time(YOUR_TIMER_NAME2) [clock clicks]

To break the iRule execution and display the page...

eval [call YOUR_DEBUG_IRULE_NAME::DEBUGPAGE]

Sample iRule integration...

when HTTP_REQUEST {

    #
    # THIS IS JUST AN EXAMPLE CODE TO SHOW HOW THE DEBUG PAGE WORKS
    # YOU MAY USE YOUR OWN SNIPPETS TO TEST THE FUNCTIONALITY
    #

    #
    # Collect Debug information
    #
    # Note: Each debug(name) variable will be listed 
    #       in the response HTML page
    #

    set debug(ORIG_HOST) [HTTP::host]
    set debug(ORIG_URI) [HTTP::uri]

    #
    # Collect Timestamp information 
    #
    # Note: Each time(name) variable will be a dedicated perf 
    #       counter and included in the HTML response page
    #
    # To start a timestamp:
    #
    # set time(timestamp_name) [clock clicks]
    #
    # To finish a timestamp:
    #
    # lappend time(timestamp_name) [clock clicks]
    #

    set time(Total) [clock clicks]

    if { [HTTP::uri] starts_with "/test1" } then {

        # Test 1: Meassure the time taken to generate a AES key

        set time(AES_Keygen) [clock clicks]

        set debug(aes_key) [AES::key 256]

        lappend time(AES_Keygen) [clock clicks]

    } elseif { [HTTP::uri] starts_with "/test2" } then {

        # Test 2: Meassure the time taken to rewrite HOST and URI

        set time(HOST_URI_rewrite) [clock clicks]

        HTTP::header replace Host "www.domain.de"
        HTTP::uri "/somefolder[HTTP::uri]"

        lappend time(HOST_URI_rewrite) [clock clicks]

        set debug(NEW_HOST) [HTTP::host]
        set debug(NEW_URI) [HTTP::uri]

    }

    lappend time(Total) [clock clicks]

    #
    # EVAL the TCL script fetched from the Debug Page procedure
    #
    # Note: The iRule used to store the Debug-Procedure is  
    #       "YOUR_DEBUG_IRULE_NAME" with "DEBUGPAGE" proc name.
    #

    eval [call YOUR_DEBUG_IRULE_NAME::DEBUGPAGE]

}

Code :

when RULE_INIT {

#
# Proc based Debug-Page with statistical performance counters
#

# Configure the sample window size
set static::sample_frame 60 ;# seconds

# Configure the statistical cutoff value to supress outliers
set static::sample_cutoff 10;# percent

# Stop further iRule processing and TCP::close the connection
set static::stop_futher_processing 1;# bolean

}
proc DEBUGPAGE { return {

#
# The proc will return a TCL script containing the debug page code.
#

# Rendering HTML response head/body

set temp(http_response) "





Debug Information
"

# Rendering HTML response debug table

if { [array exist debug] } then {

foreach temp(var) "[lsort -dictionary [array names debug]]" {
append temp(http_response) "
"

}

append temp(http_response) "

$temp(var)
$debug($temp(var))
"

} else {

append temp(http_response) "

--NA----NA--

"

}

# Enumarating active time frames and calculating statistical information

foreach temp(timeframe_name) [array names time] {

# Checking validity of current time frame

if { [llength $time($temp(timeframe_name))] == 2 } then {

# Calculating the total time of current time frame

set temp(timeframe_last_sum) [expr {[lindex $time($temp(timeframe_name)) 1] - [lindex $time($temp(timeframe_name)) 0] - 2 }]

# Preparing HTML table for the current time frame

append temp(http_response_table_last) "

$temp(timeframe_name)$temp(timeframe_last_sum)
"

# Storing the total time of the current time frame into session table

table set -subtable $temp(timeframe_name) [lindex $time($temp(timeframe_name)) 0] $temp(timeframe_last_sum) indef $static::sample_frame

# Init statistics calculation 

set temp(timeframe_table_keys_values) ""

# Enumarating the stored time frame values for current time frame

foreach temp(timeframe_table_key) [table keys -subtable $temp(timeframe_name)] {

# Fetching next stored time frame for current time frame

set temp(timeframe_table_key_value) [table lookup -subtable $temp(timeframe_name) $temp(timeframe_table_key)]

# Checking if next stored time frame still exist (race conditions)

if { $temp(timeframe_table_key_value) ne "" } then {

lappend temp(timeframe_table_keys_values) $temp(timeframe_table_key_value)

}

}

if { $temp(timeframe_table_keys_values) ne "" } then {

# Calculating raw statistics for current time frame

set temp(timeframe_table_keys_values_sorted) [lsort -integer $temp(timeframe_table_keys_values) ]
set temp(timeframe_table_keys_count) [llength $temp(timeframe_table_keys_values_sorted)]
set temp(timeframe_table_keys_min) [lindex $temp(timeframe_table_keys_values_sorted) 0]
set temp(timeframe_table_keys_max) [lindex $temp(timeframe_table_keys_values_sorted) end]
set temp(timeframe_table_keys_sum) [expr "[join $temp(timeframe_table_keys_values_sorted) " + " ]"]
set temp(timeframe_table_keys_avg) [expr { $temp(timeframe_table_keys_sum) / $temp(timeframe_table_keys_count) }]

# Preparing HTML table for raw statistics of current time frame

append temp(http_response_table_avg) "

$temp(timeframe_name)$temp(timeframe_table_keys_min)$temp(timeframe_table_keys_max)$temp(timeframe_table_keys_avg)$temp(timeframe_table_keys_count)
"

# Calculating cutoff statistics for current time frame

set temp(timeframe_table_keys_count_cutoff_mask) [expr { int($temp(timeframe_table_keys_count) * "0.$static::sample_cutoff" )}]
set temp(timeframe_table_keys_values_cutoff) [lrange $temp(timeframe_table_keys_values_sorted) [expr { 0 + $temp(timeframe_table_keys_count_cutoff_mask) }] [expr { $temp(timeframe_table_keys_count) - 1 - $temp(timeframe_table_keys_count_cutoff_mask) }]]
set temp(timeframe_table_keys_count_cutoff) [llength $temp(timeframe_table_keys_values_cutoff)]
set temp(timeframe_table_keys_min_cutoff) [lindex $temp(timeframe_table_keys_values_cutoff) 0]
set temp(timeframe_table_keys_max_cutoff) [lindex $temp(timeframe_table_keys_values_cutoff) end]
set temp(timeframe_table_keys_sum_cutoff) [expr "[join $temp(timeframe_table_keys_values_cutoff) " + " ]"]
set temp(timeframe_table_keys_avg_cutoff) [expr { $temp(timeframe_table_keys_sum_cutoff) / $temp(timeframe_table_keys_count_cutoff) }]

# Preparing HTML table for cutoff statistics of current time frame

append temp(http_response_table_avg_cutoff) "

$temp(timeframe_name)$temp(timeframe_table_keys_min_cutoff)$temp(timeframe_table_keys_max_cutoff)$temp(timeframe_table_keys_avg_cutoff)$temp(timeframe_table_keys_count_cutoff)2 * $temp(timeframe_table_keys_count_cutoff_mask)
"

}

}

}

# Rendering HTML response Last CPU clicks table

if { [info exists temp(http_response_table_last)]  } then {

append temp(http_response) "
Last CPU clicks

$temp(http_response_table_last)


Counter Name
Last CPU Clicks
"

}

# Rendering HTML response Avg CPU clicks (raw) table

if { [info exists temp(http_response_table_avg)]  } then {

append temp(http_response) "
Avg CPU clicks (raw)

$temp(http_response_table_avg)


Counter Name
Min CPU Clicks
Max CPU Clicks
Avg CPU Clicks
# Samples
"

}

# Rendering HTML response Avg CPU clicks (-% cutoff) table

if { [info exists temp(http_response_table_avg)]  } then {

append temp(http_response) "
Avg CPU clicks (-$static::sample_cutoff % cutoff)

$temp(http_response_table_avg_cutoff)


Counter Name
Min CPU Clicks
Max CPU Clicks
Avg CPU Clicks
# Samples
# Cutoff
"

}

# Rendering HTML response head/body

append temp(http_response) "

"


HTTP::respond 200 content $temp(http_response) noserver "Content-Type" "text/html"

# Stopping further iRule processing

if { $static::stop_futher_processing } then {
event disable all
TCP::close
return
} else {

unset -nocomplain temp
unset -nocomplain time

}

}}

Tested this on version:

12.0