#!/usr/bin/perl

#
# Name: elapse.pl
# Author: Jim Schnitter
# Modified: Lionel Bartlett
# Modified date: 26 May 2009
# Purpose: Determines the elapsed time for each specified operationin an LDAP trace log.
# Version: 4.1.6

# 2.1 - Fixed bug in getmsgid.  On error conditions it would match the paren
#       enclosing the NDS error number.
# 3.0 - Added option to specify the LDAP operation, -m. 
#       Removed option to specify the number of lines, -n.  Reasonable defaults
#       are specified for each operation.
#       Created print_op_details function.  It does the actually line printing.
#       If the operation doesn't finish, call print_op_details.
#	Added a verbose_usage option, --help.
#
# Note: Use -D for program debugging.
# 3.1 - Changed the GetMsgID value to be the IP & Port number only
#       Perform additional  checks for the GetMsgID in more functions to prevent unrelated LDAP messages being displayed
#	Added option "-c". When used only displays completed LDAP queries
#	Updated --Help message
# 3.1.1	Display IP Address and Port next to elapsed time
#	Report statistics for total instances per second
# 3.2	Added IP Address filter which supports multiple addresses, comma seperated and wildcards (use , or ; to seperate)
#	Output displays the LDAP operation as well as any NDS error reported. Could be used to create a CSV file for stats.
# 3.2.1 CSV output added with option "x", usage "-x -c"
# 3.2.2 Added Start and End time to CSV output
# 3.2.3 Added additional stats to show percentages for delays
# 3.2.4 Added Average and Peak TPS stats, with start, end and peak times
# 3.2.5 Moved stats around to get more data out in case of devide by zero error.
#       Added "Abandon" to list of LDAP operations and DoAbandon stats
# 3.2.6 Added file name to CSV output
# 3.2.7 Added Search base, parameters and filter info to text and CSV output
# 3.2.8 Fixed bug where the Do* operation was not being printed out
# 3.3.0 Always display all operation detail 
#       Default mode: Search
#       Default time: 3 seconds
#       Parameter order not significant
#       Using -x includes -c
#       Fixed getopts statement. was 'getopts("x:-:', now 'getopts("x-:'
# 4.0   Fixed bug where ALL LDAP op details were not always being displayed
#       Always display stats for total number of operations for each second elapsed
#       In statistics section: Added asterisk next to seconds indicating which match and exceed "-t" parameter value
# 4.1   Report total number of instances where an attribute is used in a filter. For indexing analysis
#       Must specify -t AND not be 0 for the report to be presented
# 4.1.1 Cleaned up leading zeros in attribute stats.    
# 4.1.2 Track attribute instances for each resposne time second
# 4.1.3 Check for attribute search type to assist with index creation type
# 4.1.4 Fix index substring check rule
# 4.1.5 Changed logic for locating the end of a thread. This allows for reporting on all attributes in a search
#       Report 'UnBinds' when '-m all' is used
# 4.1.5b Corrected message output when TAG missing from line
# 4.1.5c Changed rule for detecting LDAP tags, because the THRD tag data precedes TAGS data in dstrace
# 4.1.6 Added option to only display stats without ops being written to file... heaps faster.
#       Wrap "Object Name" in quotes so column in CSV output works in spreadsheet
#       Added support for DoCompare and DoExtended LDAP operations

$VERSION = "4.1.6";

format TOTALPERTIME =
     @> @>>>>               @>>>>>                @###.##%
$ind, $t, $_, $percentPerTime
.

format TPS =
            Average TPS: @###.## (Transactions Per Second)
$transpersec
.

use warnings;
use Getopt::Std;

sub getmsgid($);
sub gettime($);
sub print_op_details($$$$);
sub usage();
sub verbose_usage();
my @timearray = ();
my @attrnamearray = ();
my @attrcountarray = ([],[]);
$totalattrcount=0;
$modetype="";

%options=();
getopts("x-:i:t:m:D:c:s",\%options);

if (defined $options{"-"}) {
        if ($options{"-"} =~ /help/) {
                verbose_usage();
        } else {
                usage();
        }
}


if (defined $options{c}) {
	$completed = 0;
} else {
	$completed = 1;
}

if (defined $options{s}) {
	$showops = 0;
} else {
	$showops = 1;
}

if (defined $options{x}) {
	$csv = 1;
	$completed = 0;
} else {
	$csv = 0;
}

if (defined $options{t}) {
	$sec_time = $options{t};
} else {
	$sec_time = 3;
}

if (defined $options{i}) {
	$ip_addr_filter = $options{i};
	$ip_addr_filter =~ s/\./\\./g;		# escape dots
	$ip_addr_filter =~ s/(,|;)/|/g;		# change commas to pipe
	$ip_addr_filter =~ s/\*/.*/g;		# escape astrisk
	$ip_addr_filter =~ s/ //g;		# remove spaces
} else {
	$ip_addr_filter = ".*";
}

# DoSearch| DoModify| DoAdd| DoDelete| DoBind| DoModRDN| DoAbandon| DoExtended | DoCompare

if (!defined $options{m}) {
	$mode = "DoSearch";
	$modetype="default";
} elsif ($options{m} =~ /all/i) {
	$mode = "DoSearch|DoModify|DoAdd|DoDelete|DoBind|DoModRDN|DoExtended|DoCompare";
	$modetype="all";
} elsif ($options{m} =~ /search|modify|add|delete|bind|modrdn|extended|compare/i ) {
	$mode = "Do$options{m}";
	$modetype="specified";
} else {
	usage();
}

if (defined $options{D}) {
	$debug = 1;
}

if (@ARGV == 1) {
	$in = $ARGV[0];
} else {
	usage();
}

sub attrIndexing {

        # Generate the indexing report displayed when using "-t" with a value greater than zero

 	@attrdata=();
	$idx=0;
	foreach $fattr ( @attrnamearray ) {
		$attrcount=sprintf( "%5s", $attrcountarray[$idx][0]);
		$attpercent=sprintf( "%5.2f", ($attrcountarray[$idx][0]/$totalattrcount)*100);
		
		$seconddata="";
		for $secidx ( $sec_time .. $#{ $attrcountarray[$idx] } ) {
			$realsec=$secidx-1;
			if ( exists $attrcountarray[$idx][$secidx] ) {
			   $attrindivcount=$attrcountarray[$idx][$secidx]."    ";
			   if ( $attrindivcount =~ m/(^.{4})/ ) { $attrindivcount=$1; }
			   $seconddata="$seconddata $realsec"."s".":$attrindivcount ";
			}
		}
		
		$atname="$fattr                          ";
		if ( $atname =~ m/(^.{30})/ ) { $atname=$1; }		
 		$attrdata[$idx]="$attrcount\t $attpercent\t   $atname  $seconddata";		
		$idx++;
	}
	
	print "\n\nAttribute Statistics:\n\n";
	print "  Report of the total number of instances where the attribute was used in a filter AND\n";
	print "  the response time exceeded the specified delay (parameter -t). The higher the total \n";
	print "  the more likely that indexing that attribute could speed up search times.\n";
	print "  Generaly attributes for which response times longer than 3 seconds are reported\n";
	print "  should be considered for indexing. (The data below exludes wildcard only searches.)\n\n";
	print "  The 'Type' column indicates whether a Value or Substring search was performed. When creating\n";
	print "  an index a decision is required between these index types. The column indicates which type\n";
	print "  to consider. The attribute name will appears twice IF both search types were used.\n\n"; 
	print "  Delays to LDAP reponses involve more then simply non-indexed attributes. The host OS and\n";
	
	# Report Header
	print "  the number of LDAP modifications per second need to be considered.\n\n";
	print "\tTotal  % Total    Type Attribute Name\t\t    Response times and total attributes for that second\n";

	print "\t-----  -------    ---- --------------\t\t    ---------------------------------------------------\n";
	foreach $fattr ( reverse sort @attrdata ) {
		print "\t$fattr\n";
	}
	print "\n";
}

# Read the entire file into an array
open (IN, $in) || die "Can't open $in\n";
@trace = <IN>;
$len = @trace;
$t=0;


# Used to keep stats on total number of searches, searches that meet our exceed
# the specified search time (-t) and a counter to determine average time per
# search.

$ind="";
$num_ops = 0;
$num_time_ops = 0;
$num_warnings = 0;
$separator = "-" x 80;
$op_type ="";
#$ipchecked=0;
$firstlogtime=0;
$firstlogsecs=0;
$peak_tps=0;
$current_tps_sec=0;
$current_tps_count=0;
$peak_time="";
$current_time="";
$total_abandoned=0;
$searchParam1="";
$searchParam2="";
$searchParam3="";
$attrnames="";
$attname="";

if ($debug) { print "IP Filter (regex): $ip_addr_filter"; }

if ($csv) { print "File Name,IP Address,Port,Operation,Object Name,NDS Error,Search Base,Search Parameters,Search Filter,Start Time,End Time,Elapsed Time\n";}

for ($c1 = 0; $c1 < $len; $c1++) {
	
	if ( ($modetype eq "all" ) && ($trace[$c1] =~ /DoUnbind/) ) {
		## print "$separator\n\n";	
		## print $trace[$c1];
	} 
	
	if ($trace[$c1] =~ /$mode/i && getmsgid($trace[$c1]) =~ /$ip_addr_filter/ ) {
	
		# Get the start time
		$start_time = gettime($trace[$c1]);
			
		# Get the search message id
		$start_msgid = getmsgid($trace[$c1]);
	
		#Op Type
		if ( $trace[$c1] =~ m/( Do\w+)/ ) {
			$op_type = $1;
		}
		
		$opname="";
		$searchParam1="";
		$searchParam2="";
		$searchParam3="";
			
		# Find the end time
		ENDTIME: for ($c2 = $c1 + 1; $c2 < $len; $c2++) {
		
		        if ( $trace[$c2] =~ /Search request/ && $start_msgid eq getmsgid($trace[$c2]) ) { 
				$searchParam1 = $trace[$c2+1];
				$searchParam1 =~ s/\n|\t|base: //g;
				$searchParam1 =~ s/,/./g;
				
				$searchParam2 = $trace[$c2+2]; 
				$searchParam2 =~ s/\n|\t/ /g;
				$searchParam2 =~ s/,/./g;
				
				$searchParam3 = $trace[$c2+3];
				$searchParam3 =~ s/\n|\t|filter: //g;
				$searchParam3 =~ s/,/./g;
			    	
			} #if
		
			if ( $trace[$c2] =~ m/DoAbandon/ && $start_msgid eq getmsgid($trace[$c2]) ) { 
				$total_abandoned++;
			}
			
			# Get bind name	
			if ($trace[$c2] =~ m/Bind name:(.*), version:/) {
				$opname = $1;
				$opname =~ s/,/./g;
			} else {
				if ($trace[$c2] =~ m/modify: dn \((.[^)]*)/) {
					$opname = $1;
					$opname =~ s/,/./g;
				}
			}
								
			if ( $trace[$c2] =~ /operation result/ && $start_msgid eq getmsgid($trace[$c2]) ) {
					
 
 			# Error Reported
 			if ( $trace[$c2] =~ m/error: (.[^)]*\))/ ) {
				$nds_error = $1;
			} else {
				$nds_error = "none";
			}
 
			# Get the end time
			$end_time = gettime($trace[$c2]);

			# Calculate the delta time
			@start_fields = split (/:/, $start_time);
			$start_secs = $start_fields[0]*3600 + $start_fields[1]*60 + $start_fields[2];

			@end_fields = split (/:/, $end_time);
			$end_secs = $end_fields[0]*3600 + $end_fields[1]*60 + $end_fields[2];

			if ( $firstlogtime eq 0 ) {
				$firstlogtime = $start_time;
				$firstlogsecs = $start_secs;
			}

			# Keep stats of peak TPS
			if ($current_tps_sec eq $start_secs) {
				$current_tps_count++;
			} else {
				
				# Set peak TPS value
				if ( $current_tps_count > $peak_tps) {
					$peak_tps = $current_tps_count ;
					$peak_time = $current_time;
				}
				
				# Reset TPS count for current second
				$current_tps_sec = $start_secs;
				$current_tps_count = 1;
				$current_time = $start_time;
			}

			$delta_time = $end_secs - $start_secs;
			
			#----------------------------------------#
			# 		Gather Stats		 #
			if ( exists $timearray[$delta_time] ) {
				$timearray[$delta_time] = $timearray[$delta_time] + 1;
			} else {
				$timearray[$delta_time] = 1;
			}
			#----------------------------------------#
			
			$num_ops++;
					
			if ( $delta_time >= $sec_time ) {
				$num_time_ops++;
			
				if ($csv) { 
					if ( $start_msgid =~ m/\((.[^:]*)/ ) {		# Get the IP Address
						$ip_addr = $1 ;
					}
				
					if ( $start_msgid  =~ m/:(.[^\)]*)/ ) {		# Get the port number
						$port = $1 ;
					}
					
					print "$in,$ip_addr,$port,$op_type,$opname,$nds_error,$searchParam1,$searchParam2,$searchParam3,$start_time,$end_time,$delta_time\n"; 	# Write CSV output
				} else {
					if ( $showops ) {					
						print "$separator\n\n";
									    	
						print_op_details($c1, $c2, $len, \@trace);
						print ">>> elapsed time = $delta_time seconds\n\n";		# Write standard output
					}
					
					### Gather attribute stats for indexing ##
					# Get the name of the attributes involved
					
					$attrnames=$searchParam3;
					
					while ( $attrnames =~ m!\((\w+)=(.[^\)]*)!g ) {
						$attname=$1;
						$attrvalue=$2;
						$fattr=0;
						$idx=0;
						$attrsearchtype="";
						
						if ( $attrvalue ne "*" ) {
							
							if ( $attrvalue =~ m/^\*/ ) {
							   $attrsearchtype="S  ";
							} else {
							   $attrsearchtype="V  ";
							}
							
							$attname=$attrsearchtype." ".$attname;
							
							if ( grep { $_ eq $attname} @attrnamearray ) {
								
				      			   foreach $fattr ( @attrnamearray ) {
				      			   	
				      			   	if ( $fattr eq $attname) {
				      			   	      
				      			              $attrcountarray[$idx][0]=++$attrcountarray[$idx][0];
				      			              # $delta_time
				      			              $attrcountarray[$idx][$delta_time+1]=++$attrcountarray[$idx][$delta_time+1];
				      			              $totalattrcount=$totalattrcount+1;

				      			 	}
				      			         $idx++;			      			  
				      			   }
				      			   
				      			}  else {
					    		   $s=@attrnamearray;
							   $attrnamearray[$s]=$attname;
							   $attrcountarray[$s][0]=1;
							   
							   # $delta_time
							   $attrcountarray[$s][$delta_time+1]=1;
							   $totalattrcount=$totalattrcount+1;

							   $s++;
						    	} #if else
				      			
					    	} #if
						
					} # while

				}
			

			} 
			last ENDTIME;
			}
			
		}
		
		if ($c2 eq $len && $completed && ! $csv) {
			$num_warnings++;
			if ( $showops ) {
				#print "$separator\n\n";	
				print_op_details($c1, $c2, $len, \@trace);
				print ">>> WARNING: Can't find the end of operation\n\n";
			}
		}
		
	}
}

if (! $csv) {
	
	print ("File: $in:\n");
	
	if ($mode =~ /\|/) {
		print ("\tAll LDAP Operations: $num_ops\n");
		print ("\tTotal Ops Abandoned: $total_abandoned \n");
		
		if ( $total_abandoned > 0 ) {
			$percentAbandonded=$total_abandoned/$num_ops;
		} else { $percentAbandonded=0; }
	
		$percentAbandonded = sprintf("%0.6f", $percentAbandonded);

		print ("\t  Percent Abandoned: $percentAbandonded %\n");			
	
		if ( $sec_time > 0 ) {
			$percentover=int(($num_time_ops/$num_ops)*1000)/1000;
			print ("\tLDAP Operations taking $sec_time seconds or greater: $num_time_ops ($percentover)\n");
			
			#print ("\tLDAP Operations taking $sec_time seconds or greater: $percentover %\n");
		}
		if ( $num_warnings > 0 ) {
			print ("\n\tAll LDAP Operations not completed: $num_warnings\n");
		}
	} else {
		print ("\tTotal LDAP $mode Operations: $num_ops\n");
	
		if ( $sec_time > 0 ) {
			print ("\tLDAP $mode Operations taking $sec_time seconds or greater: $num_time_ops\n\n");
		}
		if ( $num_warnings > 0 ) {
			print ("\tLDAP $mode Operations not completed: $num_warnings\n\n");
		}
	}
	
	# Report Statistics Per Second
	
	print "\nStatistics:\n";
	print "\tSeconds\t\tTotal Requests\t\tPercentage\n";
	
	$~ = "TOTALPERTIME";
	$timeexceeded=0;
	
	foreach (@timearray) {
		
		if ( $_ ) {
   		   $percentPerTime=($_/$num_ops)*100;
		   if ( $t >= $sec_time && $sec_time != 0 ) {$ind="*"; $timeexceeded=1; } else { $ind=""; }
		   write;
		}
		$t++;
	} 


	# Attribute Indexing
	if ( $timeexceeded == 1 ) {
		attrIndexing;
	}
	
	print ("\n");
	print ("        First operation: $firstlogtime \n");			
	print ("         Last operation: $end_time \n");

	$totaltracelength=$end_secs-$firstlogsecs;
	print ("           Trace Length: $totaltracelength seconds\n");	
	print ("              Peak Time: $peak_time\n");
	print ("               Peak TPS: $peak_tps\n");

	if ( $totaltracelength > 0 ) { 
		$transpersec=int(($num_ops/$totaltracelength)*1000)/1000;
		print ("            Average TPS: $transpersec (Transactions Per Second)\n");
	} else {
 	print ("            Average TPS: Transactions Per Second can not be calculated, trace is Zero seconds long.\n");
		print ("                         The cause may be that the trace has wrapped.\n");
	}
	print ("\n");	


	
}

#################################################################################################################
#						Start of Sub-Functions						#
#################################################################################################################

sub getmsgid($) {
	my ($string) = @_;

	# Regex checks that message id is (IP:Port)(MsgId:MsgType)
	# 9/15 - Added minimal matching to the (MsgId:MsgType) part

	$ipaddr = $string;
	$thread = $string;
	
	if ($ipaddr =~ m/(\(\d+\.\d+\.\d+\.\d+:\d+\))/ ) {
		$ipaddr=$1;
	} else {
		$ipaddr ="(0.0.0.0:0)";
	}
	
	if ( $thread =~ m/(\(0x.[^:]*)/ ) {
		$thread = $1;
	} else { $thread ="0x-1" ; }

	if (! $ipaddr eq "" && ! $thread eq "" ) {
		if ($debug) { print "[DEBUG] getmsgid: returns $1\n"; }
		return "$ipaddr $thread";
	} else {
		die "getmsgid: can't find valid message id in $string\n";
	}
}

sub getmsgIP($) {
	my ($string) = @_;

	# Get IP Addr if it exists in a string
	$ipaddr = $string;
	if ($ipaddr =~ m/(\d+\.\d+\.\d+\.\d+:\d+)/ ) { $ipaddr=$1; } else { $ipaddr="" ;}
	return $ipaddr;
}

sub getmsgTHRD($) {
	my ($string) = @_;

	# Check if THREAD # exists in a string
	
	$thread = $string;
	if ( $thread =~ m/(\(0x.[^:]*)/ ) { $thread = $1; } else { $thread = "" ;}
	return $thread;
}


sub gettime($) {
	my ($string) = @_;

	if ($string =~ /(..:..:..)/) {
		if ($debug) { print "[DEBUG] gettime: returns $1\n"; }
		return $1;
	} else {
		die "gettime: can't find valid time in $string\n";
	}
}

# Based on the operation type, print a reasonable number of lines. The
# split and joins are used to remove all the html from an iMonitor
# trace.
			
sub print_op_details($$$$) {
	($op_start,$op_finish,$trace_len,$trace_ref) = @_;
		
	if ($$trace_ref[$op_start] =~ /DoSearch/) {
		$lines = 5;
	} elsif ($$trace_ref[$op_start] =~ /DoModify/) {
		$lines = 4;
	} elsif ($$trace_ref[$op_start] =~ /DoAdd|DoDelete|DoBind|DoModRDN/) {
		$lines = 2;
	}

	$currline = $op_start;
	$lineschecked=0;
	$lastmessage="";
	$foundTag=0;
	$foundTAB=0;
	$processNonTag=1;
	
	if ( $trace_len <= 500 ) { $lines=$trace_len -1 ; } else {$lines=500; }
	
	do

  	  {
  	  	if ( ! $$trace_ref[$currline] eq "" ) {
  	  		
  	  	    if ( $$trace_ref[$currline] !~ /Connection.*closed|Monitor|closing connection/ ) {
  	 
			if ($foundTAB && $$trace_ref[$currline] =~ /^LDAP: /) {$processNonTag=0;} 
			
			if ($$trace_ref[$currline] =~ /LDAP: /) {$foundTag=1;} 
	  	  	
	  	  	if ( $foundTag || $processNonTag) {
				if ( (getmsgid($start_msgid) eq getmsgid($$trace_ref[$currline]) ) || ( getmsgIP($$trace_ref[$currline]) eq "" ) ) {
					print "$$trace_ref[$currline]";
					$lastmessage = $$trace_ref[$currline];
			
				  	if ($$trace_ref[$currline] =~ /^\t/) {$foundTAB=1;} 
  					  	
					if ($foundTag && $$trace_ref[$currline] =~ /Sending operation result|Forcing abandon on|DoAbandon/) {
						$lineschecked=$lines;
					}
				} 
				
			        $lineschecked++;
			}
		   }
				
		   $currline++;
		   $foundTag=0;
	
		}
	  }

	while ($currline <= $trace_len && $lineschecked <= $lines);

	$op_finish=$lastmessage;
}

sub verbose_usage() {
	die "\nVersion: $VERSION\n\nelapse.pl [options] tracefile\nOptions:\n\n\n\n-s\tShow statistics only for LDAP operations\n\n-x\tCSV output\n\t(Must be used with -c, e.g. -x -c)\n\n-c\tOnly report completed LDAP requests\n\n-t\tseconds\tprint operations that take this time or longer\n\t\t\(optional - defaults to 0\)\n\n-i\tIP Address Filter, comma separated or wildcards\n\t\t(Example: 10.10.10.1,10.10.2.*)\n\n-m\tmode\tone of bind,search,modify,add,delete,modrdn or all\n\t\t\(optional - defaults to all\)\n\n(Option order is significant)\n\nAttribute report is generated when specifying -t with a non-zero value.\n\n";
}

sub usage() {
	die "\nUsage: elapse.pl -x -s -c -t <secs> -i <idaddr1,ipaddr2,...> -m <mode> tracefile\n\nOr ...\n\nUsage: elapse.pl --help\n\n(Option order is significant)\n";
}