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 Page


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 NameLast 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 NameMin CPU ClicksMax CPU ClicksAvg 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 NameMin CPU ClicksMax CPU ClicksAvg 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
Updated Jun 06, 2023
Version 2.0

Was this article helpful?

No CommentsBe the first to comment