[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
        ][data session ohost]   [var MV_PAGE global][/log]
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

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;

## 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(),
                = $Vend::Session->{benchtimes_count}
                        = Vend::Interpolate::tag_counter($Global::Variable->{BENCHTIMES_COUNTER});

        # Start the benchtimes

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),

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 --------------

=head1 NAME

benchtimes -- utility to analyze benchtimes logging for Interchange


  benchtimes [-n count] [-t timespec] file


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.


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;


=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.


my %start;

my $first = 0;
my $now = time();
if($opt{t}) {
	my $minus = time_to_seconds($opt{t});
	$first = $now - $minus;

while(<>) {
	my ($ip, $path, $sessionid, $pid, $time, $id, $bench) = split /\t/, $_;
	next unless $time > $first;
	if($bench) {
		$session_time{$sessionid} += $bench;
		$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;

	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


=head1 AUTHOR

Mike Heins, <mike (at domain) perusion.com>.

=head1 BUGS

None known at this time.


More information about the interchange-users mailing list