Index: openacs-4/packages/xotcl-request-monitor/www/long-calls.tcl
===================================================================
RCS file: /usr/local/cvsroot/openacs-4/packages/xotcl-request-monitor/www/long-calls.tcl,v
diff -u -N -r1.4.2.11 -r1.4.2.12
--- openacs-4/packages/xotcl-request-monitor/www/long-calls.tcl 24 Nov 2022 19:26:45 -0000 1.4.2.11
+++ openacs-4/packages/xotcl-request-monitor/www/long-calls.tcl 27 Nov 2022 17:21:26 -0000 1.4.2.12
@@ -8,6 +8,7 @@
{lines:naturalnum 20}
{readsize:naturalnum 100000}
{pool:word,multiple ""}
+ {by_starttime:boolean 0}
} -properties {
title:onevalue
context:onevalue
@@ -75,7 +76,13 @@
#
# Remember pool settings for the number-of-lines filter
#
-set filterQuery &[export_vars {pool:multiple}]
+set filterQuery &[export_vars {pool:multiple lines by_starttime}]
+ns_log notice "filterQuery = '$filterQuery'"
+
+set toggle_request_start [expr {!$by_starttime}]
+set toggle_request_start_url [export_vars -base long-calls {pool:multiple lines {by_starttime $toggle_request_start}}]
+set toggle_request_time_title [expr {$by_starttime ? "Click to order by endtime" : "Click to order by starttime"}]
+
#
# Map in the found pools empty to "default"
#
@@ -119,23 +126,45 @@
set queuetime [dict get $time queuetime]
set filtertime [dict get $time filtertime]
set runtime [dict get $time runtime]
+ set totaltime [format %8.6f [expr {$queuetime + $filtertime + $runtime}]]
+
if {[dict exists $time start]} {
+ #
+ # We have the precise start time.
+ #
set s0 [dict get $time start]
- set start_secs [ns_time seconds $s0]
- set start_msecs [string range [ns_time format $s0] end-6 end]
- set start [clock format $start_secs -format %H:%M:%S]$start_msecs
+ set timestamp_start [ns_time format $s0]
} else {
- set start ""
+ #
+ # We have only the end time precise to the second (legacy
+ # data). Also in these cases, compute the approximate
+ # start time by subtracting from the end time the total
+ # runtime.
+ #
+ #set start_old "$hours.000000"
+ set timestamp_end [clock scan "$year $mon $day $hours" -format "%Y %b %d %H:%M:%S"].000001
+ set timestamp_start [expr {$timestamp_end-($queuetime + $filtertime + $runtime)}]
}
- set totaltime [format %8.6f [expr {$queuetime + $filtertime + $runtime}]]
+ set start_secs [ns_time seconds $timestamp_start]
+ set start_msecs [string range 000000[ns_time microseconds $timestamp_start] end-5 end]
+ set start [clock format $start_secs -format "%H:%M:%S"].$start_msecs
+ #ns_log notice "start $start timestamp_start $timestamp_start start_msecs '$start_msecs'"
+
+ set timestamp_end [expr {$timestamp_start + $queuetime + $filtertime + $runtime}]
+ set end_secs [ns_time seconds $timestamp_end]
+ set end_msecs [string range 000000[ns_time microseconds $timestamp_end] end-5 end]
+ set end [clock format $end_secs -format "%H:%M:%S"].$end_msecs
+
+ set request_time_title [clock format $start_secs -format "%Y %b %d\n%H:%M:%S"].$start_msecs
+ append request_time_title " -\n" [clock format $end_secs -format "%H:%M:%S"].$end_msecs
+
set color(queuetime) [::xo::colorize_slow_calls -fast 0.001 -warning 0.50 -danger 1.00 $queuetime]
set color(filtertime) [::xo::colorize_slow_calls -fast 0.010 -warning 1.00 -danger 2.00 $filtertime]
set color(runtime) [::xo::colorize_slow_calls -fast 0.010 -warning 5.00 -danger 10.00 $runtime]
set color(totaltime) [::xo::colorize_slow_calls -fast 0.010 -warning 5.00 -danger 10.00 $totaltime]
- set color(start) "small info bg-info bg-opacity-10"
} else {
lassign {"" "" "" ""} start queuetime filtertime runtime
- lassign {"" "" "" ""} color(start) color(queuetime) color(filtertime) color(runtime)
+ lassign {"" "" ""} color(queuetime) color(filtertime) color(runtime)
set totaltime $time
set color(totaltime) [::xo::colorize_slow_calls -fast 0.010 -warning 3.00 -danger 10.00 $totaltime]
}
@@ -148,20 +177,42 @@
}
set request [ns_quotehtml $url]
set request [::xo::regsub_eval {user_id=([0-9]+)} $request {::xo::subst_user_link user_id= \1} user_id=]
- append rows "" \
- "| $start | " \
- "$queuetime | " \
- "$filtertime | " \
- "$runtime | " \
- "$totaltime | " \
- "$year $mon $day $hours | " \
- "$userinfo | " \
- "$iplink | " \
- "$pool | " \
- "$request | " \
- "
\n"
+ #ns_log notice "start $start [string length $start] end $end [string length $end]"
+ if {$by_starttime} {
+ set time $start
+ } else {
+ set time $end
+ }
+ set row [subst {
+ | $time |
+ $queuetime |
+ $filtertime |
+ $runtime |
+ $totaltime |
+ $userinfo |
+ $iplink |
+ $pool |
+ $request |
+
+ }]
+ if {!$by_starttime} {
+ append rows $row
+ } else {
+ append order_start($timestamp_start) $row \n
+ }
}
+if {$by_starttime} {
+ foreach start_time [lsort -real -decreasing [array names order_start]] {
+ append rows $order_start($start_time)
+ }
+ set request_time_label "Request Start"
+} else {
+ # rows are already in the order of end time
+ set request_time_label "Request End"
+}
+
+
set doc(title) "Long Calls"
set context [list $doc(title)]