Index: openacs-4/packages/xotcl-request-monitor/xotcl-request-monitor.info =================================================================== RCS file: /usr/local/cvsroot/openacs-4/packages/xotcl-request-monitor/xotcl-request-monitor.info,v diff -u -r1.10.2.5 -r1.10.2.6 --- openacs-4/packages/xotcl-request-monitor/xotcl-request-monitor.info 6 Sep 2016 17:45:09 -0000 1.10.2.5 +++ openacs-4/packages/xotcl-request-monitor/xotcl-request-monitor.info 28 Nov 2016 08:20:17 -0000 1.10.2.6 @@ -8,7 +8,7 @@ t request-monitor - + Gustaf Neumann WU Vienna Request Monitor with user tracking functionality @@ -34,7 +34,7 @@ BSD-Style 2 - + Index: openacs-4/packages/xotcl-request-monitor/tcl/throttle_mod-procs.tcl =================================================================== RCS file: /usr/local/cvsroot/openacs-4/packages/xotcl-request-monitor/tcl/throttle_mod-procs.tcl,v diff -u -r1.43.2.5 -r1.43.2.6 --- openacs-4/packages/xotcl-request-monitor/tcl/throttle_mod-procs.tcl 21 Nov 2016 18:31:39 -0000 1.43.2.5 +++ openacs-4/packages/xotcl-request-monitor/tcl/throttle_mod-procs.tcl 28 Nov 2016 08:20:17 -0000 1.43.2.6 @@ -273,14 +273,14 @@ return [my array get active] } - Throttle instproc add_url_stat {method url time_used key pa content_type} { + Throttle instproc add_url_stat {method url partialtimes key pa content_type} { #ns_log notice "Throttle.add_url_stat($method,$url,$time_used,$key,$pa,$content_type)" catch {my unset running_url($key,$url)} #my log "### unset running_url($key,$url) $errmsg" if {[string match "text/html*" $content_type]} { [Users current_object] add_view $key } - response_time_minutes add_url_stat $url $time_used $key + response_time_minutes add_url_stat $url [dict get $partialtimes ms] $key } Throttle instforward report_url_stats response_time_minutes %proc Throttle instforward flush_url_stats response_time_minutes %proc @@ -318,8 +318,14 @@ [self class] append log "$entry\n" [self class] incr count } - TraceLongCalls instproc add_url_stat {method url time_used key pa content_type} { + TraceLongCalls instproc add_url_stat {method url partialtimes key pa content_type} { regexp {^([^?]+)[?]} $url . url + # + # conntime: time spent in connection thread in ms, not including queuing times + # totaltime: time since start of the request + #set conntime [expr {int(([dict get $partialtimes runtime] + [dict get $partialtimes filtertime]) * 1000)}] + set totaltime [dict get $partialtimes ms] + #ns_log notice "url=<$url> time_used $time_used" if { $url in {/register/ / /dotlrn/} } { # @@ -328,18 +334,18 @@ incr ::agg_time($url) $time_used incr ::count(calls:$url) } - if {$time_used > 5000} { + if {$totaltime > 5000} { if {$url eq "/register/"} { set color unexpected - } elseif {$time_used > 10000} { + } elseif {$totaltime > 10000} { set color red - } elseif {$time_used > 6000} { + } elseif {$totaltime > 6000} { set color orange } else { set color yellow } - incr ::count(longcalls:$color) - catch {my log [self args]} + incr ::count(longcalls:$color) + catch {my log [list $url $totaltime $key $pa $content_type]} } next } @@ -1388,14 +1394,30 @@ next } -throttle proc ms {-start_time} { - if {![info exists start_time]} { - set start_time [ns_conn start] +# +# Use the feature of connection pool unmapping to determine, if we can +# use "ns_conn partialtimes". We can't use the latter directly, since +# this file is typically loaded from a non-connection thread. +# +if {[catch {ns_server unmap "GET /*JUST_FOR_TESTING*"}]} { + # + # Older version of NaviServer or AOLserver + # + throttle proc partialtimes {} { + set t [ns_time diff [ns_time get] [ns_conn start]] + set ms [expr {[ns_time seconds $t]*1000 + [ns_time microseconds $t]/1000}] + return [list ms $ms runtime [expr {$ms/1000.0}] filtertime 0 queuetime 0 accepttime 0] } - set t [ns_time diff [ns_time get] $start_time] - #my log "+++ $t [ns_conn url]" - set ms [expr {[ns_time seconds $t]*1000 + [ns_time microseconds $t]/1000}] - return $ms +} else { + # + # Use variant based on "ns_conn partialtimes" + # + throttle proc partialtimes {} { + set d [ns_conn partialtimes] + set t [ns_time diff [ns_time get] [ns_conn start]] + lappend d ms [expr {[ns_time seconds $t]*1000 + [ns_time microseconds $t]/1000}] + return $d + } } throttle proc get_context {} { @@ -1494,7 +1516,7 @@ # the next procs are for the filters (registered from the -init file) #### throttle proc postauth args { - #my log "+++ [self proc] [ad_conn url] auth ms [my ms] [ad_conn isconnected]" + #my log "+++ [self proc] [ad_conn url] auth ms [my partialtimes] [ad_conn isconnected]" #my do set ::cookies([set :requestor]) [ns_set get [ns_conn headers] Cookie] set r [my check] if {$r < 0} { @@ -1516,14 +1538,14 @@ } } throttle proc trace args { - #my log "+++ [self proc] <$args> [ad_conn url] [my ms] [ad_conn isconnected]" + #my log "+++ [self proc] <$args> [ad_conn url] [my partialtimes] [ad_conn isconnected]" # OpenACS 5.2 bypasses for requests to /resources the user filter # in these cases pre- or postauth are not called, but only trace. # So we have to make sure we have the needed context here my get_context #my log "CT=[ns_set array [ns_conn outputheaders]] -- [set :url]" - my add_url_stat ${:method} ${:url} [my ms] ${:requestor} ${:pa} \ + my add_url_stat ${:method} ${:url} [my partialtimes] ${:requestor} ${:pa} \ [ns_set get [ns_conn outputheaders] Content-Type] my unset context_initialized return filter_ok Index: openacs-4/packages/xotcl-request-monitor/www/index.adp =================================================================== RCS file: /usr/local/cvsroot/openacs-4/packages/xotcl-request-monitor/www/index.adp,v diff -u -r1.8.2.3 -r1.8.2.4 --- openacs-4/packages/xotcl-request-monitor/www/index.adp 6 Sep 2016 17:45:09 -0000 1.8.2.3 +++ openacs-4/packages/xotcl-request-monitor/www/index.adp 28 Nov 2016 08:20:17 -0000 1.8.2.4 @@ -16,7 +16,8 @@
avg. #connection threads @thread_avgs.current@, avg. busy @thread_avgs.busy@ Summaries:Aggregated URL Statistics, Last 100 Requests, - Throttle Statistics + Throttle Statistics, + Long calls Index: openacs-4/packages/xotcl-request-monitor/www/long-calls.adp =================================================================== RCS file: /usr/local/cvsroot/openacs-4/packages/xotcl-request-monitor/www/long-calls.adp,v diff -u -r1.2.2.1 -r1.2.2.2 --- openacs-4/packages/xotcl-request-monitor/www/long-calls.adp 18 May 2016 12:39:10 -0000 1.2.2.1 +++ openacs-4/packages/xotcl-request-monitor/www/long-calls.adp 28 Nov 2016 08:20:17 -0000 1.2.2.2 @@ -1,5 +1,18 @@ doc +

+ Lines: 20, +50, +100, +200, +500, +1000, +2000, +5000, +10000 +

+ +