[ic] Did you know about AutoEnd? (part of a series)
Mike Heins
mike at perusion.com
Sun Apr 17 08:22:53 EDT 2005
Interchange has an Autoload directive for catalog.cfg, which allows you
to run catalog-specific code prior to normal processing. But did you
know that there is also AutoEnd?
AutoEnd is a directive which accepts ITL code:
AutoEnd <<EOITL
[log
file=logs/page.log
interpolate=1
][data session ohost] [var MV_PAGE global][/log]
EOITL
Or a subroutine name:
AutoEnd some_routine1
(As of Interchange 5.4, you will be able to add multiple
Autoload and Autoend calls on separate lines, but as of this
date you can have only one directive specification.)
The AutoEnd routine runs after all page processing is complete,
shortly before Interchange closes the catalog database and
terminates the page transaction.
As an example, here is a logging setup which uses both AutoLoad and
AutoEnd to benchmark each access to an Interchange catalog. It has
recently been added to the Interchange distribution as an extension
"benchtimes".
It employs two global subroutines. To enable, all you do is add on the
end of catalog.cfg:
Autoload benchtimes_start
AutoEnd benchtimes_end
# WARNING: If you currently use an Autoload with ITL code you may
# not be able to use this. If you use an Autoload like "admin_links"
# you have to add the benchtimes_start before it:
#
# Autoload benchtimes_start admin_links
The Autoload routine runs at the beginning of the page transaction,
and pulls a few pieces of information from the user session and
the HTTP connection information. It starts the benchmark timer
(with a UserTag called "benchtimes"), uniquely identifies the
page access with a counter, then logs that to a file.
The AutoEnd routine runs after the page is complete and reads
the benchmark timer and adds the time it computed to the log
information and logs it again.
The enabling code containing the subroutines and a UserTag used by
those subroutines is at the end of this message. (Attached to this
message is a small tool that does an analysis if the created log.)
In summary, you can use AutoEnd to do logging, cleanup, or
other functions automatically after every page.
### end message text, start addition to interchange.cfg
###
### Add this chunk to the end of your interchange.cfg file to enable
### benchtimes
###
UserTag benchtimes Order start display
UserTag benchtimes Routine <<EOR
sub {
my ($start, $display) = @_;
my @times = times();
if($start or ! defined $::Instance->{benchtimes_start}) {
$::Instance->{benchtimes_start} = 0;
$::Instance->{benchtimes_times} = [ @times ];
for(@times) {
$::Instance->{benchtimes_start} += $_;
}
}
my $current_total;
if($display or ! $start) {
my $benchtimes_times = $::Instance->{benchtimes_times};
for(@times) {
$current_total += $_;
}
unless ($start) {
$current_total = sprintf '%.3f', $current_total - $::Instance->{benchtimes_start};
for(my $i = 0; $i < 4; $i++) {
$times[$i] = sprintf '%.3f', $times[$i] - $benchtimes_times->[$i];
}
}
return $current_total;
}
return;
}
EOR
## You can change the location
Variable BENCHTIMES_LOG_FILE logs/bench.log
Variable BENCHTIMES_COUNTER logs/bench.counter
## Subroutine to start the logging process
GlobalSub benchtimes_start <<EOS
sub {
my @bench_things = qw( ip path session pid time count bench );
my %hash = (
ip => $CGI::remote_addr,
path => $CGI::request_uri,
session => $Vend::SessionID,
pid => $$,
time => time(),
);
$hash{count}
= $Vend::Session->{benchtimes_count}
= Vend::Interpolate::tag_counter($Global::Variable->{BENCHTIMES_COUNTER});
# Start the benchtimes
$Vend::Interpolate::Tag->benchtimes(1);
Vend::Util::logData(
$Global::Variable->{BENCHTIMES_LOG_FILE},
@hash{@bench_things}
);
return;
}
EOS
GlobalSub benchtimes_end <<EOS
sub {
my @bench_things = qw( ip path session pid time count bench );
my %hash = (
ip => $CGI::remote_addr,
path => $CGI::request_uri,
session => $Vend::SessionID,
pid => $$,
time => time(),
count => $Vend::Session->{benchtimes_count},
bench => $Vend::Interpolate::Tag->benchtimes(undef,1),
);
Vend::Util::logData(
$Global::Variable->{BENCHTIMES_LOG_FILE},
@hash{@bench_things}
);
return;
}
EOS
--
Mike Heins
Perusion -- Expert Interchange Consulting http://www.perusion.com/
phone +1.765.647.1295 tollfree 800-949-1889 <mike at perusion.com>
Software axiom: Lack of speed kills.
-------------- next part --------------
#!/usr/bin/perl
=head1 NAME
benchtimes -- utility to analyze benchtimes logging for Interchange
=head1 SYNOPSIS
benchtimes [-n count] [-t timespec] file
=head1 DESCRIPTION
This small tool analyzes the CPU usage of Interchange by session id
and IP address. It shows the top users in seconds of time and number of hits.
=cut
use Getopt::Std;
use strict;
my %opt;
getopts('n:t:', \%opt);
use POSIX qw/strftime/;
my %session_time;
my %session_hits;
my %total_time;
my %total_hits;
my %earliest;
my %bigpages;
my %latest;
my %info;
# Parses a time specification such as "1 day" and returns the
# number of seconds in the interval, or undef if the string could
# not be parsed.
sub time_to_seconds {
my($str) = @_;
my($n, $dur);
($n, $dur) = ($str =~ m/(\d+)[\s\0]*(\w+)?/);
return undef unless defined $n;
if (defined $dur) {
local($_) = $dur;
if (m/^s|sec|secs|second|seconds$/i) {
}
elsif (m/^m|min|mins|minute|minutes$/i) {
$n *= 60;
}
elsif (m/^h|hour|hours$/i) {
$n *= 60 * 60;
}
elsif (m/^d|day|days$/i) {
$n *= 24 * 60 * 60;
}
elsif (m/^w|week|weeks$/i) {
$n *= 7 * 24 * 60 * 60;
}
else {
return undef;
}
}
$n;
}
=head1 OPTIONS
=over 4
=item -n count
The number of entries to display for each type. This
would display 16 of each:
benchtimes -n 16 /var/lib/interchange/foundation/logs/bench.log
Default is 10.
=item -t timespec
Determines how far back in time you want to go. Accepts a standard Interchange
time specification, i.e. "1 day" or "3 hours". This would summarize for
the past day:
benchtimes -t 1d /var/lib/interchange/foundation/logs/bench.log
Default is not set, meaning all log lines are analyzed.
=cut
my %start;
my $first = 0;
my $now = time();
if($opt{t}) {
my $minus = time_to_seconds($opt{t});
$first = $now - $minus;
}
while(<>) {
chomp;
my ($ip, $path, $sessionid, $pid, $time, $id, $bench) = split /\t/, $_;
next unless $time > $first;
if($bench) {
$session_hits{$sessionid}++;
$session_time{$sessionid} += $bench;
$total_hits{$ip}++;
$total_time{$ip} += $bench;
$bigpages{$id} = $bench;
$info{$id} = "ip=$ip path=$path pid=$pid time=$bench";
unless($start{$id}) {
warn "Couldn't find start for $_\n";
}
elsif(! $time) {
warn "No end time for $_\n";
}
$latest{$ip} = $time;
$latest{$sessionid} = $time;
}
else {
$start{$id} = $time;
$earliest{$ip} ||= $time;
$earliest{$sessionid} ||= $time;
}
}
my %display = (
session_time => \%session_time,
session_hits => \%session_hits,
total_hits => \%total_hits,
total_time => \%total_time,
);
my %fmt = (
session_time => '%9.3f seconds',
session_hits => '%6d hits',
total_hits => '%6d hits',
total_time => '%9.3f seconds',
bigpages => '%9.3f seconds',
);
my $started;
my $n = $opt{n} || 10;
no strict 'refs';
for my $tag (sort keys %display) {
my $ref = $display{$tag}
or warn "No reference found for $tag. Skip.\n", next;
print "\n" if $started++;
my @keys = sort { $ref->{$b} <=> $ref->{$a} } keys %$ref;
print "Displaying top $n by $tag\n";
print "---------------------------------\n";
for(my $i = 0; $i < $n; $i++) {
my $id = $keys[$i] or next;
my $early = strftime('%m-%d %H:%M:%S', localtime($earliest{$id}));
my $late = strftime('%m-%d %H:%M:%S', localtime($latest{$id}));
printf "%-20s $fmt{$tag} (from %s to %s)\n", $id, $ref->{$id}, $early, $late;
}
}
BIGP: {
my $tag = 'bigpages';
my $ref = \%bigpages
or warn "No reference found for bigpages. Skip.\n", next;
print "\n" if $started++;
my @keys = sort { $ref->{$b} <=> $ref->{$a} } keys %$ref;
print "Displaying top $n by $tag\n";
print "---------------------------------\n";
for(my $i = 0; $i < $n; $i++) {
my $id = $keys[$i] or next;
printf "%-20s $fmt{$tag}\n(%s)\n", $id, $ref->{$id}, $info{$id};
}
}
=head1 SEE ALSO
http://cvs.icdevgroup.org/cgi-bin/cvsweb/extensions/benchtimes
=head1 AUTHOR
Mike Heins, <mike (at domain) perusion.com>.
=head1 BUGS
None known at this time.
=cut
More information about the interchange-users
mailing list