slowops

#!/usr/bin/perl -w
# Find particular operations and display their etime distribution

use strict;
use warnings;

$::VERSION = 0.3;

sub version()
{
	print STDERR "$0 version $::VERSION\n";
	exit 0;
}

sub usage()
{
	print STDERR "Usage: $0 [-s] [-j] [-e etime] [op]\n";
	exit 1;
}

my %opt = (
	's' => 0,                   # Summary mode
	'j' => 0,                   # JSON logs
	'e' => -1,                  # Etime
	'h' => 0,                   # Help
	'v' => 0,                   # Version
);

my $op = 'SEARCH';

while (@ARGV) {
	my $arg = shift @ARGV;
	if ($arg =~ m{^-s$|^--summary$}) {
		$opt{'s'} = 1;
	} elsif ($arg =~ m{^-j$|^--json$}) {
		# JSON::XS is significantly faster than JSON::PP
		if (eval{require JSON::XS}) {
			$opt{j} = JSON::XS->new;
		} elsif (eval{require JSON::PP}) {
			$opt{j} = JSON::PP->new;
		} else {
			die "Cannot locate a JSON module\n";
		}
	} elsif ($arg =~ m{^-e$|^--etime$}) {
		$opt{e} = shift @ARGV;
		usage unless defined $opt{e};
	} elsif ($arg =~ m{^-h$|^--help$}) {
		$opt{h} = 1;
	} elsif ($arg =~ m{^-v$|^--version$}) {
		$opt{v} = 1;
	} else {
		$op = $arg;
		last;
	}
}

version if $opt{v};
usage if $opt{h};

my %details;
my %quantize;
my $scale = 0;

# Calculating mean
my $sum = 0;
my $values = 0;
# Calculating median
my $lowest = undef;
my $highest = undef;
# Calculating mode
my %mode;

sub updatestats
{
	my $etime = shift;
	my $details = shift;

	$sum += $etime;
	$values++;
	$lowest = $etime unless defined($lowest);
	$highest = $etime unless defined($highest);
	$lowest = $etime if $etime < $lowest;
	$highest = $etime if $etime > $highest;
	$mode{$etime} = 0 unless exists $mode{$etime};
	$mode{$etime}++;

	my $bucket = 1;
	do {
		$quantize{$bucket} = [] unless exists $quantize{$bucket};
		if ($etime <= $bucket) {
			push @{$quantize{$bucket}}, $details;
			if (scalar(@{$quantize{$bucket}}) > $scale) {
				$scale = scalar(@{$quantize{$bucket}});
			}
			return;
		}
		$bucket *= 2;
	} while (1);
}

while (<>) {
	chomp;
	# JSON log format
	if ($opt{'j'}) {
		my $record = $opt{j}->decode($_);
		next unless $record->{request}->{operation} eq $op;
		my $etime = $record->{response}->{elapsedTime};
		print "$_\n" if $opt{'e'} != -1 && $etime >= $opt{'e'};
		updatestats($etime, $_) if $opt{'s'};
		next;
	}
	# Traditional log format
	if (my ($tuple) = m{$op REQ.*(conn=-?\d+ op=\d+ msgID=\d+)}) {
		$details{$tuple} = $_;
		next;
	}
	# Traditional log format
	if (my ($tuple,$remainder) = m{$op RES .*(conn=-?\d+ op=\d+ msgID=\d+)( +.*)}) {
		if (exists $details{$tuple}) {
			my $details = $details{$tuple};
			delete $details{$tuple}; 
			my $etime = "";
			$etime = $1 if $remainder =~ m{ etime=(\d+)};
			if ($opt{'e'} != -1 && $etime >= $opt{'e'}) {
				print "$details$remainder\n";
			}
			updatestats($etime, $details) if $opt{'s'};
		}
		next;
	}
	# Combined log format
	if (my ($tuple,$remainder) = m{$op .*(conn=-?\d+ op=\d+ msgID=\d+)( +.*)}) {
		my $etime = "";
		$etime = $1 if $remainder =~ m{ etime=(\d+)};
		if ($opt{'e'} != -1 && $etime >= $opt{'e'}) {
			print "$_\n";
		}
		updatestats($etime, $_) if $opt{'s'};
		next;
	}
}

exit 0 unless $opt{'s'};
format STDOUT_TOP =
 value  ------------------------Distribution------------------------ count
.
format = 
@>>>>> |@<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< @<<<<<<<<
$::bucket, $::bar, $::count
.
foreach our $bucket (sort {$a <=> $b} (keys %quantize)) {
	our $count = scalar(@{$quantize{$bucket}});
	our $bar = "@" x ($count * 60.0 / $scale);
	write;
}

if ($values > 0) {
	my $key_max = undef;
	my $val_max = 0;
	foreach (keys %mode) {
		if ($mode{$_} > $val_max) {
			$val_max = $mode{$_};
			$key_max = $_;
		}
	}
	printf "Mean:   %.02f\n", $sum / $values;
	printf "Median: %.02f\n", ($highest - $lowest) / 2;
	printf "Mode:   %.02f\n", $key_max;
}

1;

__END__

=head1 NAME

slowops -  analyze operation performance in OpenDJ log files

=head1 SYNOPSIS

slowops [-j] -s op

slowops [-j] -e min op

slowops -h

slowops -v

=head1 DESCRIPTION

OpenDJ access log files record the elapsed time ("etime") taken by each LDAP
operation. However if the server is busy finding slow operations is awkward, and
finding any trends in the data is difficult.

This tool analyzes OpenDJ access logs in a couple of ways. The statistics mode
shows a graph of operation performance, and some basic figures like
mean/mode/median. The etime mode reports all operations that take longer than a
certain time to complete.

=head1 OPTIONS

=over

=item B<-j> parse JSON-formatted logs.

=item B<-h> display help text.

=item B<-v> report the tool version.

=item B<-s> report statistics after reading all the data. The graph output is a
power-of-two frequency distribution, modelled on dtrace(1)'s quantize function.

=item B<-e> report operations which have etimes larger than C<I<min>>.

=item B<op> the LDAP operation being analyzed, which should be one of C<BIND>,
C<SEARCH>, C<ADD>, C<DELETE>, C<MODIFY>, C<MODIFYDN>.

=back

=head1 EXAMPLE

$ slowops -s ADD < access

 value  ------------------------Distribution------------------------ count
     1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                         193
     2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 317
     4 |                                                             3
     8 |                                                             3
    16 |                                                             1
Mean:   1.68
Median: 4.50
Mode:   2.00

=head1 SEE ALSO

L<dtrace(1)>

L<http://opendj.forgerock.org>

=head1 AUTHOR

Chris Ridd E<lt>chris.ridd@forgerock.comE<gt>

=head1 COPYRIGHT

Copyright (c) 2012-2017 Chris Ridd. All rights reserved. This tool is free
software; you can redistribute it and/or modify it under the same terms as Perl
itself.