Last month, I’ve needed to diagnose 2 issues with a foswiki installation.
The first is the constant issue of pinpointing performance problems, the second with session persistence not persisting.
Both of these needed some form of logging to track when and to whom they were happening, so I figured the easiest thing to do was to use Apache to log what I needed.
Performance monitoring
Apache can log ‘The time taken to serve the request, in microseconds.’, and it can log HTTP response header values. So I added a little code to the foswiki installation to output a HiRes timer of how long it took to render the request, and set up my log as:
#add a 'performance' log
LogFormat "%h %l %{SCRIPT_URI}e%q %u %t %>s %Ts (%DuS) foswiki: %{X-Foswiki-Monitor-Rendertime}o " performance
CustomLog logs/performance_log performance
Using this log, we can compare configuration changes and loads vs both perl execution times and (it seems) some measure of communication times.
Session Cookie logging
In this foswiki’s case, there was a mix of http/https, ipv4/ipv6, Client SSL Certificates and hotfixed RewriteRules that I was suspicious of. So given that it worked for my connections more often than not, I wondered if there were conflicts of session cookies between ssl and non-ssl, or something more insidious.
So I started logging session cookies (guid’s)
#add a 'session cookies and strikeone' log
LogFormat "%h %{HTTP_HOST}e %>s \"%r\" %{pid}P \"%{SSL_CLIENT_S_DN_CN}e\" %{FOSWIKISID}C %{SFOSWIKISID}C %{FOSWIKISTRIKEONE}C " session
CustomLog logs/session_log session
In both cases, these log files let me pinpoint what the problem was not – and then have that inspiration that fixed the worst of it.
X-Foswiki-Monitor-renderTime patch
I’ll either add this to foswiki 1.2.0, or make a plugin for it, but if you want to see how long things take to render, apply this patch:
NOTE: you will need to install the Time::HiRes CPAN library
diff --git a/core/lib/Foswiki.pm b/core/lib/Foswiki.pm
index 4771f71..d26bd80 100644
--- a/core/lib/Foswiki.pm
+++ b/core/lib/Foswiki.pm
@@ -838,6 +838,9 @@ BOGUS
}
}
+ $this->{response}->pushHeader( 'X-Foswiki-Monitor-renderTime',
+ $this->{request}->getTime() );
+
$this->generateHTTPHeaders( $pageType, $contentType, $text, $cachedPage );
# SMELL: null operation. the http headers are written out
diff --git a/core/lib/Foswiki/Request.pm b/core/lib/Foswiki/Request.pm
index 2ce2e15..a06af69 100644
--- a/core/lib/Foswiki/Request.pm
+++ b/core/lib/Foswiki/Request.pm
@@ -36,6 +36,14 @@ use Assert;
use Error ();
use IO::File ();
use CGI::Util qw(rearrange);
+use Time::HiRes ();
+
+sub getTime {
+ my $this = shift;
+ my $endTime = [Time::HiRes::gettimeofday];
+ my $timeDiff = Time::HiRes::tv_interval( $this->{start_time}, $endTime );
+ return $timeDiff;
+}
=begin TML
@@ -69,6 +77,7 @@ sub new {
remote_user => undef,
secure => 0,
server_port => undef,
+ start_time => [Time::HiRes::gettimeofday],
uploads => {},
uri => '',
};
Time::HiRes
