Update and Cleanup of the log analyzer script for the supafly application.

README also provided.

pelab/supafly/scripts/README

+README File for using the scripts to analyze the logs of the supafly 
+application.
+
+Author : Venkat Chakravarthy <vchakra@flux.utah.edu>
+Date   : October 09, 2006
+
+CONTENTS OF THE CHECKOUT:
+1) The checked out directory contains the log files generated by profiling the 
+   supafly application on Emulab, Planetlab and Pelab. These are in the 
+   respective "logs_<name_of_lab>" subdirectories.
+
+2) There is also a sample set of logs in the "logs_sample" subdirectory.
+
+3) The main PERL script is the "log_analyzer.pl" file.
+
+4) There is also a shell script file called "plot.sh" that contains Gnuplot 
+   commands to plot the graphs. This shell script gets called by the above 
+   PERL script. The shell script was written to automate the process of 
+   generating the graphs.
+
+
+RUNNING THE SCRIPT:
+1) The checked in version of the script will run fine and generate the graphs 
+   for the logs_emulab, logs_pelab and the logs_sample log files.
+
+   NOTE: To run it on the logs_planetlab a slight modification has to be done!
+         This is explained in Step 3.
+
+   The following example shows how to run the script on the Emulab logs.
+
+   USAGE  : ./log_analyzer.pl <middleman> <sender> <receiver> <<fillme>lab>
+
+   EXAMPLE:
+
+   % ./log_analyzer.pl logs_emulab/middleman.log logs_emulab/sender.log 
+     logs_emulab/receiver.log emulab
+
+
+2) You must provide all the four command line arguments. Running the script 
+   will create a generated/<<fillme>lab> subdirectory and place all the 
+   generated data(.dat) and graph(.eps) files there. The following files will
+   be generated for the above emulab example.
+
+   a) emulab.dat - This is the data file fed to Gnuplot. It contains two 
+                   columns, "middleman timestamps in diffs" and 
+                   "(receiverTS - senderTS)"
+
+   b) emulab_stat_file - This contains statistical information like the max,
+                   min, mean, variance and standard deviation of three 
+                   datasets:  the perceived duration at the middleman
+                              the timestamps recorded at the middleman
+                              the (rcvTS-sndTS) computed at sender and receiver
+
+   c) emulab_lag.eps - The plot of the "(rcvTS-sndTS)" on the Y-axis against 
+                   the "timestamp diffs recorded at the middleman" on the 
+                   X-axis. All values are in seconds.    
+   
+   d) There are some other generated temporary files as well. Ignore those.
+
+
+3) To run the script for the checked in Planetlab logs, modify the 
+   "log_analyzer.pl" script at the section marked "NOTE" in the source code.
+   Instructions on commenting and uncommenting are provided in the source code
+   itself.
+

pelab/supafly/scripts/log_analyzer.pl

@@ -4,42 +4,108 @@
 #-----------------------------#
 #This script analyzes the log files of the supafly application.
 
+
+
+
+
+## Initialization
+print "-----------------------------------------------------------------------------\n";
+print "                                Log Analysis \n\n";
+print "                All files are in the \"generated\" subdirectory \n";
+print "\n USAGE  : ./log_analyzer.pl <middleman> <sender> <receiver> <<fillme>lab>\n";
+print "\n Example: ./log_analyzer.pl middleman.log sender.log receiver.log planetlab\n";
+print "-----------------------------------------------------------------------------\n\n";
+
 $numArgs = $#ARGV +1;
 
+if ($numArgs != 4){
+    die "Incorrect Usage!\n";
+}
+ 
 # foreach $argnum (0 .. $#ARGV) {
 #    print "$ARGV[$argnum]\n";
 # }
 
-#print `clear`; 
 
-print "------------------------------------------\n";
-print "              Log Analysis \n";
-print "\n USAGE: perl log_analyzer.pl <logfilename>\n";
-print "------------------------------------------\n\n";
 
-#Process the Logfile
 
-open(LOG,"$ARGV[0]") or die "Unable to open logfile: $!\n\n";
 
-print "The name of the log file was: $ARGV[0] \n\n";
+## Make the output directories if they do not exist
+`mkdir generated`;
+`mkdir generated/$ARGV[3]`;
+`mkdir generated/$ARGV[3]/tmp`;
+$dirpath = "./generated/$ARGV[3]";
+$tmppath = "./generated/$ARGV[3]/tmp";
+
+
+
+
+
+#Read the imput logfiles
+
+open(LOG1,"$ARGV[0]") or die "Unable to open logfile: $!\n\n";
+open(LOG2,"$ARGV[1]") or die "Unable to open logfile: $!\n\n";
+open(LOG3,"$ARGV[2]") or die "Unable to open logfile: $!\n\n";
+
+print "\nThe name of the middleman log file was : $ARGV[0] \n\n";
+print "The name of the sender log file was    : $ARGV[1] \n\n";
+print "The name of the receiver log file was  : $ARGV[2] \n\n";
+print "The analysis is being done for         : $ARGV[3] \n\n";
+
+
+
+
+
+## Process the log files to get the lines that have relevant data
+## Processing the Middleman Log
+$tmpfilename = &prepend_tmp("mid_tmp_dump.txt");
+open(MID_TMP_DUMP, ">$tmpfilename") or die " $!\n";
+
+while(<LOG1>){
+    print MID_TMP_DUMP if /\bBLOCKTIME\b/i;
+}
+close(LOG1);
+close(MID_TMP_DUMP);
+
+## Processing the Sender Log
+$tmpfilename = &prepend_tmp("snd_tmp_dump.txt");
+open(SND_TMP_DUMP, ">$tmpfilename") or die " $!\n";
+
+while(<LOG2>){
+    print SND_TMP_DUMP if /\bTIME\b/i;
+}
+close(LOG2);
+close(SND_TMP_DUMP);
 
-open(TMP_DUMP, ">tmp_dump.txt") or die " $!\n";
+## Processing the Receiver Log
+$tmpfilename = &prepend_tmp("rcv_tmp_dump.txt");
+open(RCV_TMP_DUMP, ">$tmpfilename") or die " $!\n";
 
-while(<LOG>){
-    print TMP_DUMP if /\bBLOCKTIME\b/i;
+while(<LOG3>){
+    print RCV_TMP_DUMP if /\bTIME\b/i;
 }
-close(LOG);
-close(TMP_DUMP);
+close(LOG3);
+close(RCV_TMP_DUMP);
+
 
-#@name = split(/./, $ARGV[0]);
 
-open(TMP_DUMP, "tmp_dump.txt") or die " $!\n";
-open(VALUES, ">values.txt") or die " $!\n";
+
+
+## Get the values from the processed Middleman logfile into arrays
+## The format of the input for the Middleman should be
+##    <Tag>      <Block_Num> <Duration> <Text>    <Finish_Time>
+## BLOCKTIME(de):    16         323       at    1160440380.674084
+##
+# Middleman Processing
+$tmpfilename1 = &prepend_tmp("mid_tmp_dump.txt");
+$tmpfilename2 = &prepend("middleman_values.dat");
+open(MID_TMP_DUMP, "$tmpfilename1") or die " $!\n";
+open(MID_VALUES, ">$tmpfilename2") or die " $!\n";
 
 $printed = 0;
 $i = 0;
 $baseT = 0.0;
-while (<TMP_DUMP>) {
+while (<MID_TMP_DUMP>) {
     @tmp = split;  
     if($printed == 0)
     {
@@ -48,55 +114,201 @@ while (<TMP_DUMP>) {
 	$printed = 1;
     }
 
+## ***********************************************************
+## *************************NOTE******************************
+## ***********************************************************
+## USE THE FOLLOWING ONLY FOR PROCESSING EMULAB AND PELAB LOGS
+## FOR PLANETLAB COMMENT THIS OUT AND UNCOMMENT THE BELOW
+
+## START_NEW_CODE
     if (!$i) {
-	$baseT = $tmp[3];
+	$baseT = $tmp[4];
 	++$i;
     }
     
-    $tmp1 = $tmp[3]-$baseT;
-    print VALUES "$tmp1 $tmp[1]\n";
-    push (@duration, $tmp[1]);
-    push (@finish_time, $tmp1); 
+    $time_diff = $tmp[4]-$baseT;
+    
+    ## Write the values to a text file for Gnuplot processing
+    ## FORMAT:     <Block_Num> <Time-Diff> <Duration>
+    print MID_VALUES "$tmp[1]   $time_diff   $tmp[2]\n";
+
+    ## At the same time put the values into an array as well
+    push (@blocknum, $tmp[1]);
+    push (@duration, $tmp[2]);
+    push (@finish_time, $time_diff); 
+## END_NEW_CODE
+
+
+## ***********************************************************
+## *************************NOTE******************************
+## ***********************************************************
+## USE THE FOLLOWING ONLY FOR PROCESSING PLANETLAB LOGS
+## FOR ALL OTHERS COMMENT THIS OUT AND UNCOMMENT THE ABOVE
+
+## START_OLD_CODE
+#     if (!$i) {
+#         $baseT = $tmp[3];
+#         ++$i;
+#     }
+
+#     $time_diff = $tmp[3]-$baseT;
+#     ## Write the values to a text file for Gnuplot processing
+#     ## FORMAT:       <Time-Diff> <Duration>
+#     print MID_VALUES "$time_diff  $tmp[1]\n";
+#     push (@duration, $tmp[1]);
+#     push (@finish_time, $time_diff);
+## END_OLD_CODE
+
+}
+close(MID_VALUES);
+close(MID_TMP_DUMP);
+
+
+
+
+
+## Sender and Receiver logfile processing 
+## The format of the input for the Sender should be
+##    <Tag>      <Block_Num>   <Send_Time>
+##    TIME           56       1160440380.7564
+##
+## The format of the input for the Receiver should be
+##    <Tag>      <Block_Num>   <Receive_Time>
+##    TIME           16       1160445708.338260
+
+#Sender and Receiver Processing
+$tmpfilename1 = &prepend_tmp("snd_tmp_dump.txt");
+$tmpfilename2 = &prepend_tmp("rcv_tmp_dump.txt");
+open(SND_TMP_DUMP, "$tmpfilename1") or die " $!\n";
+open(RCV_TMP_DUMP, "$tmpfilename2") or die " $!\n";
+
+while (<SND_TMP_DUMP>) {
+    @tmp = split;  
+    push (@snd_time, $tmp[2]); 
+}
+
+while (<RCV_TMP_DUMP>) {
+    @tmp = split;  
+    push (@rcv_time, $tmp[2]); 
 }
-close(VALUES);
-close(TMP_DUMP);
 
-$tmp = `rm tmp_dump.txt`;
+close(RCV_TMP_DONE);
+close(SND_TMP_DUMP);
+
+
+
+
+
+## Write the final values to be plotted into a file
+$datafilename = &prepend($ARGV[3] . ".dat");
+open(SNDRCV_VALUES, ">$datafilename") or die " $!\n";
+
+my $min = &minimum($#rcv_time, $#snd_time);
+for($i=0; $i<=$min; $i++)
+{
+    my $time_diff = $rcv_time[$i] - $snd_time[$i];
+    push (@time_diff, $time_diff); 
+    my $tmp_val = $finish_time[$i];
+    print SNDRCV_VALUES "$tmp_val $time_diff\n";
+}
+close(SNDRCV_VALUES);
+
+
+
+
+
+## Clean up all unnecessary files
+#$tmp = `rm mid_tmp_dump.txt`;
+
+
+
+
+
+## Print statistics into the Statistics file as needed
+$statfilename = &prepend($ARGV[3] . "_stat_file.txt");
+open(STATS_FILE, ">$statfilename") or die " $!\n";
+
+#&print_array(@blocknum);
 
 #&print_array(@duration);
 
 #&print_array(@finish_time);
 
 $length = scalar(@duration);
-print "Length             = " . $length . "\n\n";
+print STATS_FILE "Length             = " . $length . "\n\n";
 
-# Print the statistics for the Duration
-print "Statistics for Duration\n";
-print "-----------------------\n";
-print "Max Duration       = " . &maximum(@duration) . " microseconds\n";
-print "Min Duration       = " . &minimum(@duration) . " microseconds\n";
+# Print the statistics for the Duration measured at middleman
+print STATS_FILE "Statistics for duration measured at middleman\n";
+print STATS_FILE "---------------------------------------------\n";
+print STATS_FILE "Max Duration       = " . &maximum(@duration) . " microseconds\n";
+print STATS_FILE "Min Duration       = " . &minimum(@duration) . " microseconds\n";
 $mean = &mean(@duration);
 $vari = &variance($mean, @duration);
 $std = sprintf("%.3f",sqrt($vari));
-print "Mean Duration      = " . $mean . " microseconds\n";
-print "Duration Variance  = " . $vari . " \n";
-print "Duration Std. Dev. = " . $std . " \n\n";
-
-#Print the statistics for the Finish Times
-print "Statistics for Finish Times\n";
-print "---------------------------\n";
-print "Max Finish Time(FT)= " . &maximum(@finish_time) . " microseconds\n";
-print "Min Finish Time(FT)= " . &minimum(@finish_time) . " microseconds\n";
+print STATS_FILE "Mean Duration      = " . $mean . " microseconds\n";
+print STATS_FILE "Duration Variance  = " . $vari . " \n";
+print STATS_FILE "Duration Std. Dev. = " . $std . " \n\n";
+
+#Print the statistics for the Finish Times measured at middleman
+print STATS_FILE "Statistics for timestamps measured at middleman\n";
+print STATS_FILE "-----------------------------------------------\n";
+$max_ft = &maximum(@finish_time);
+$min_ft = &minimum(@finish_time);
+print STATS_FILE "Max Finish Time(FT)= " . $max_ft . " microseconds\n";
+print STATS_FILE "Min Finish Time(FT)= " . $min_ft . " microseconds\n";
 $mean = &mean(@finish_time);
 $vari = &variance($mean, @finish_time);
 $std = sprintf("%.3f",sqrt($vari));
-print "Mean FT            = " . $mean . " microseconds\n";
-print "FT Variance        = " . $vari . " \n";
-print "FT Std. Dev.       = " . $std . " \n";
+print STATS_FILE "Mean FT            = " . $mean . " microseconds\n";
+print STATS_FILE "FT Variance        = " . $vari . " \n";
+print STATS_FILE "FT Std. Dev.       = " . $std . " \n\n";
+
+# Print the statistics for the (receiverTS - senderTS) measured at sender and receiver 
+#&print_array(@time_diff);
+print STATS_FILE "Statistics for (receiverTS - senderTS)\n";
+print STATS_FILE "--------------------------------------\n";
+$max_td = &maximum(@time_diff);
+$min_td = &minimum(@time_diff);
+print STATS_FILE "Max Time_Diff        = " . $max_td . " microseconds\n";
+print STATS_FILE "Min Time_Diff        = " . $min_td . " microseconds\n";
+$mean = &mean(@time_diff);
+$vari = &variance($mean, @time_diff);
+$std = sprintf("%.3f",sqrt($vari));
+print STATS_FILE "Mean Time_Diff       = " . $mean . " microseconds\n";
+print STATS_FILE "Time_Diff Variance   = " . $vari . " \n";
+print STATS_FILE "Time_Diff Std. Dev.  = " . $std . " \n\n";
+
+
+
+
+
+## Gnuplot Commands
+## Call the other script as follows
+$datfilename = &prepend($ARGV[3]);
+
+`./plot.sh $datfilename $min_ft $max_ft $min_td $max_td`;
 
-$tmp = `gnuplot plot.cmd; gv dur_vs_fin.eps &`;
+## Display the graph
+$fromfilename = &prepend($ARGV[3] . ".eps");
+$tofilename   = &prepend($ARGV[3] . "_lag.eps");
+`mv $fromfilename $tofilename`;
+`gv $tofilename &`;
 
-## Procedures in PERL
+
+
+
+
+## Functions
+
+sub prepend
+{
+    return $dirpath . "/" . $_[0]; 
+}
+
+sub prepend_tmp
+{
+    return $tmppath . "/" . $_[0]; 
+}
 
 sub print_array
 {

pelab/supafly/scripts/plot.cmd → pelab/supafly/scripts/plot.sh

+#!/bin/sh
+
 ## GNUPlot commands
+gnuplot << EOF
 
 set title ''
 set terminal postscript eps 20
 
-set output "dur_vs_fin.eps"
+set output "$1.eps"
 
-set xlabel 'Finish Time (seconds)' font "Times,20"
-set ylabel 'Duration (microseconds)' font "Times,20"
+set xlabel 'Timestamps as diffs (seconds)' font "Times,20"
+set ylabel 'Duration (seconds)' font "Times,20"
 
 #set format x "  %g"
 #set grid xtics ytics
@@ -14,7 +17,14 @@ set ylabel 'Duration (microseconds)' font "Times,20"
 set size 1.5,1.0
 set key top right
 
-set xrange [0:]
-set yrange [0:]
+#set xrange [$2:$3]
+#set yrange [$4:$5]
+
+#set xrange [0:]
+#set yrange [0:]
+
+set xrange [0:30]
+set yrange [0:1.2]
 
-plot 'values.txt' title "Cumulative Lag" with lines
+plot "$1.dat" title "$1 Lag" with linespoints pt 3
+EOF