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) "
$temp(var)
$debug($temp(var))
"
}
append temp(http_response) "
"
} 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
Counter Name
Last CPU Clicks
$temp(http_response_table_last)
"
}
# 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)
Counter Name
Min CPU Clicks
Max CPU Clicks
Avg CPU Clicks
# Samples
$temp(http_response_table_avg)
"
}
# 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)
Counter Name
Min CPU Clicks
Max CPU Clicks
Avg CPU Clicks
# Samples
# Cutoff
$temp(http_response_table_avg_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
}
}}
