source: gs2-extensions/parallel-building/trunk/src/bin/script/generate_gantt.pl@ 27543

#!/usr/bin/perl

use strict;
use warnings;

use Sort::Naturally;
use POSIX qw(floor strftime);

print "\n===== Generate Timing (GANTT) =====\n";

# 1. Initialization
#my $chart_width = 1024;
my $chart_width = 1536;
#my $chart_width = 2048;
print "Chart Width: " . $chart_width . "px\n";
# 1.1 Store all information extracted in a cool data structure
# - N = hostname, S = thread start, E = thread end
my $timing_data = {'M' => {'N'=>'', 'S'=>0, 'E'=>0}};
# 1.2 Check the file exists
if (!-f $ARGV[0])
{
  die("Error! File can't be read: " . $ARGV[0]);
}
my $main_log_filename = $ARGV[0];
# 1.2 From the filename we can parse in some information like the number of worker threads
my $number_of_workers = 0;
if ($main_log_filename =~ /\-W(\d+)E/)
{
  $number_of_workers = $1;
}
else
{
  die("Error! Malformed filename (expecting number of workers): " . $main_log_filename);
}
# 1.3 Initialize the data structure with the number of workers too (we don't
#     know the number of files yet, so they'll have to be adding on the fly)
for (my $i = 1; $i <= $number_of_workers; $i++)
{
  $timing_data->{'W' . $i} = {'N'=>'', 'S'=>0, 'E'=>0, 'F'=>{}};
}

# 2. Read in main log file
print " * Reading main log: " . $main_log_filename . "\n";
open(LOGIN, '<:utf8', $main_log_filename) or die("Error! Failed to open file for reading: " . $main_log_filename);
my $line = '';
my $currently_processing = {};
while ($line = <LOGIN>)
{
  # 2.1 Parse in the Master thread start time
  if ($line =~ /\[M\d?:(\d+)\] Starting on (.+)/)
  {
    $timing_data->{'M'}->{'S'} = $1;
    $timing_data->{'M'}->{'N'} = $2;
  }
  elsif ($line =~ /\[(W\d+):(\d+)\] Starting on (.+)/)
  {
    my $worker_id = $1;
    $timing_data->{$worker_id}->{'S'} = $2;
    $timing_data->{$worker_id}->{'N'} = $3;
  }
  elsif ($line =~ /\[(W\d+):(\d+)\] Processing/)
  {
    my $worker_id = $1;
    my $job_start_time = $2;
    $timing_data->{$worker_id}->{'F'}->{$job_start_time} = {'FN'=>'', 'PS'=>0, 'PE'=>0, 'E'=>0};  
    $currently_processing->{$worker_id} = $job_start_time;
  }
  # 2.3 Or we may parse in the starting times for each working thread
  # 2.4 Or we may also parse (the last encountered) completion time for each
  #     working thread
  elsif ($line =~ /\[(W\d+):(\d+)\] Process complete/)
  {
    my $worker_id = $1;
    my $job_end_time = $2;
    $timing_data->{$worker_id}->{'E'} = $job_end_time;
    my $job_start_time = $currently_processing->{$worker_id};
    $timing_data->{$worker_id}->{'F'}->{$job_start_time}->{'E'} = $job_end_time;
    delete($currently_processing->{$worker_id});
  }
  # 2.5 Finally, we may parse in the Master thread end time
  elsif ($line =~ /\[M\d?:(\d+)\] Master will exit when workers complete/)
  {
    $timing_data->{'M'}->{'E'} = $1;
  }
}
close(LOGIN);

# 3. Read each of worker logs parsing in information about the files processed
#    - each will be stored (in an associative array) against its start time
print " * Reading worker logs";
foreach my $worker_id (nsort keys %{$timing_data})
{
  my $jobs = $timing_data->{$worker_id}->{'F'};
  my $counter = 1;
  foreach my $job_start_time (sort keys %{$jobs})
  {
    my $log_filename = 'gsimport-' . $worker_id . '-' . $counter . '.log';
    print ".";
    open(WLOGIN, '<:utf8', $log_filename) or die("Error! Failed to open for reading: " . $log_filename);
    my $wline = '';
    while ($wline = <WLOGIN>)
    {
      if ($wline =~ /\[A:\d+\] SimpleVideoPlugin processing: (.+)/)
      {
        $timing_data->{$worker_id}->{'F'}->{$job_start_time}->{'FN'} = $1;
      }
      # Start of video processing (excluding as much IO as possible) 
      elsif ($wline =~ /\[C1:(\d+)\]/)
      {
        $timing_data->{$worker_id}->{'F'}->{$job_start_time}->{'PS'} = $1;
      }
      # Immediately after processing video
      elsif ($wline =~ /\[E2:(\d+)\]/)
      {
        $timing_data->{$worker_id}->{'F'}->{$job_start_time}->{'PE'} = $1;
      }
    }

    if ($timing_data->{$worker_id}->{'F'}->{$job_start_time}->{'PE'} <= 0)
    {
      print "\n[Warning - bogus log: $log_filename]";
    }

    close(WLOGIN);
    $counter++;
  }
}
print " Done!\n";

# 4. Produce CSV of information
print " * Generating timing information as CSV... ";
open(CSVOUT, '>:utf8', 'timing.csv') or die('Error! Failed to open file for writing: timing.csv');
print CSVOUT "number,id,hostname,start,end,hierarchy\n";
my $thread_counter = 1;
foreach my $thread (nsort keys %{$timing_data})
{
  my $data = $timing_data->{$thread};
  print CSVOUT $thread_counter . ',' . $thread . ',' . $data->{'N'} . ',' . strftime("%H:%M:%S", localtime($data->{'S'})) . ',' . strftime("%H:%M:%S", localtime($data->{'E'})) . ',';
  if ($thread eq 'M')
  {
    print CSVOUT '0';
  }
  else
  {
    print CSVOUT '1';
  }
  print CSVOUT "\n";
  $thread_counter++;
}
close(CSVOUT);
print "Done!\n";

# 5. Produce pretty HTML chart of timing information including jobs
print " * Generating timing information as HTML... ";
open(HTMLOUT, '>:utf8', 'gantt.html') or die('Error! Failed to open file for writing: gantt.html');
print HTMLOUT "<html>\n";
print HTMLOUT '<head>' . "\n";
print HTMLOUT '<style type="text/css">' . "\n";
print HTMLOUT 'div.thread {position:relative}' . "\n";
print HTMLOUT 'div.master {border:1px solid gray;color:white;font-weight:bold}' . "\n";
print HTMLOUT 'div.worker {background-color:green;color:white;font-weight:bold}' . "\n";
print HTMLOUT 'div.time {font-size:smaller;font-weight:normal}' . "\n";
print HTMLOUT 'div.job {background-color:transparent;color:black;border:1px solid black;display:block;font-size:smaller;position:relative;text-align:center}' . "\n";
print HTMLOUT 'span.process {z-index:-1;background-color:#C7C7C7;position:absolute}' . "\n";
print HTMLOUT "th {text-align:left}\n";
print HTMLOUT '</style>' . "\n";
print HTMLOUT '</head>' . "\n";
print HTMLOUT "<body>\n";
print HTMLOUT "<h2>Statistics</h2>\n";
print HTMLOUT "<table>\n";

my $total_duration = $timing_data->{'M'}->{'E'} - $timing_data->{'M'}->{'S'};
my $file_count = 0;
my $total_io_time = 0;
my $total_process_time = 0;
my $fastest_file = 0;
my $slowest_file = 0;
my $problem_files = 0;
foreach my $worker_id (keys %{$timing_data})
{
  if ($worker_id ne 'M')
  {
    foreach my $job_start ( keys %{$timing_data->{$worker_id}->{'F'}} )
    {
      my $process_start = $timing_data->{$worker_id}->{'F'}->{$job_start}->{'PS'};
      my $process_end = $timing_data->{$worker_id}->{'F'}->{$job_start}->{'PE'};
      my $job_end = $timing_data->{$worker_id}->{'F'}->{$job_start}->{'E'};
      if ($process_start == 0 || $process_end == 0 || $job_end == 0)
      {
        $problem_files++;
      }
      else
      {
        my $io_duration = ($process_start - $job_start) + ($job_end - $process_end);
        my $process_duration = $process_end - $process_start;
        my $total_duration = $io_duration + $process_duration;
        ###rint "[DEBUG] filename: " . $timing_data->{$worker_id}->{'F'}->{$job_start}->{'FN'} . "\n";
        ###rint "[DEBUG] start: $job_start ps: $process_start pe: $process_end end: $job_end\n";
        ###rint "[DEBUG] io: $io_duration process: $process_duration duration: $total_duration\n";
        # Running stats
        $total_io_time += $io_duration;
        $total_process_time += $process_duration;
        if ($fastest_file == 0 || $total_duration < $fastest_file)
        {
          $fastest_file = $total_duration;
        }
        if ($slowest_file == 0 || $total_duration > $slowest_file)
        {
          $slowest_file = $total_duration;
        }
      }
      $file_count++;
    }
  }
}
my $avg_processing_time = floor(($total_io_time + $total_process_time) / $file_count);

print HTMLOUT "<tr><th>Processing Time:</th><td>" . &renderTime($total_duration) . "</td></tr>\n";
print HTMLOUT "<tr><th>Processing Threads:</th><td>" . $number_of_workers . "</td></tr>\n";
print HTMLOUT "<tr><th>Files Processed:</th><td>" . $file_count . "</td></tr>\n";
print HTMLOUT "<tr><th>Problem Files:</th><td>" . $problem_files . "</td></tr>\n";
print HTMLOUT "<tr><th>Serial Processing Time:</th><td>" . &renderTime($total_process_time) . "</td></tr>\n";
print HTMLOUT "<tr><th>Serial IO Time:</th><td>" . &renderTime($total_io_time) . "</td></tr>\n";
print HTMLOUT "<tr><th>Average File Processing Time:</th><td>" . &renderTime($avg_processing_time) . "</td></tr>\n";
print HTMLOUT "<tr><th>Fastest File:</th><td>" . &renderTime($fastest_file) . "</td></tr>\n";
print HTMLOUT "<tr><th>Slowest File:</th><td>" . &renderTime($slowest_file) . "</td></tr>\n";

print HTMLOUT "</table>\n";
print HTMLOUT "<hr />\n";
print HTMLOUT "<h2>Timing Chart (Gannt)</h2>\n";
print HTMLOUT renderLine($chart_width, $timing_data->{'M'}->{'S'}, $timing_data->{'M'}->{'E'}, 'master', $timing_data->{'M'}->{'N'}, $timing_data->{'M'}->{'S'}, $timing_data->{'M'}->{'E'}, {});
foreach my $worker_id (nsort keys %{$timing_data})
{
  if ($worker_id ne 'M')
  {
    my $data = $timing_data->{$worker_id};
    print HTMLOUT renderLine($chart_width, $timing_data->{'M'}->{'S'}, $timing_data->{'M'}->{'E'}, 'worker', $worker_id . ' [' . $data->{'N'} . ']', $data->{'S'}, $data->{'E'}, $data->{'F'});
  }
}
print HTMLOUT '<div>' . "\n";
print HTMLOUT "</body>\n";
print HTMLOUT "</html>";
close(HTMLOUT);

print "Done!\n";
print "Complete!\n\n";
exit;

# /**
#  */
sub renderLine
{
  my ($table_width, $start, $end, $class, $tname, $tstart, $tend, $jobs) = @_;
  # All timings need to be relative to 0 (relative start)
  my $duration = $end - $start;
  my $rtstart = $tstart - $start;
  my $rtend = $tend - $start;
  # We need to scale these depending on the timing of this thread relative to
  # the master thread
  my $width = $chart_width;
  my $left = 0;
  if ($start != $tstart)
  {
    my $left_offset_percent = $rtstart / $duration;
    $left = $left_offset_percent * $table_width;
  }
  # - subtract any left offset from width
  $width = $width - $left;
  # - right offset directly subtracted from width 
  if ($end != $tend)
  {
    my $right_offset_percent = ($duration - $rtend) / $duration;
    my $right = $right_offset_percent * $table_width;
    $width = $width - $right;
  }
  my $html = '<div class="thread ' . $class . '" style="left:' . $left . 'px;width:' . $width . 'px;">';
  if ($class eq 'master')
  {
    $html .= '<div style="background-color:blue">';
  }
  $html .= '<div class="time" style="display:table-cell">' . &renderTime($rtstart) . '</div><div style="display:table-cell;padding-left:20px;width:100%;">' . ucfirst($class) . ': ' . $tname . '</div><div class="time" style="display:table-cell">' . renderTime($rtend) . '</div></div>';
  my $previous_jright = 0;
  foreach my $jstart (sort keys %{$jobs})
  {
    my $rjstart = $jstart - $start;
    my $rpstart = $jobs->{$jstart}->{'PS'} - $start;
    my $rpend = $jobs->{$jstart}->{'PE'} - $start;
    my $rjend = $jobs->{$jstart}->{'E'} - $start;
    my $jduration = $jobs->{$jstart}->{'E'} - $jstart;
    # Scale Job co-ordinates
    my $jleft_percent = $rjstart / $duration;
    my $jleft = floor($jleft_percent * $table_width);
    my $jwidth_percent = $jduration / $duration;
    my $jwidth = floor($jwidth_percent * $table_width);
    if ($jleft < $previous_jright)
    {
      $jleft = $previous_jright;
    } 
    if ($jleft + $jwidth > $left + $width)
    {
      $jwidth = ($left + $width) - $jleft;
    }
    # Then scale process timings within that!
    my $rpleft_percent = ($rpstart - $rjstart) / $duration;
    my $rpleft = floor($rpleft_percent * $table_width);
    my $rpwidth_percent = ($rpend - $rpstart) / $duration;
    my $rpwidth = floor($rpwidth_percent * $table_width);
    $html .= '<div class="job" style="left:' . $jleft . 'px;width:' . $jwidth . 'px" title="S:' . renderTime($rjstart) . ', PS:' . renderTime($rpstart) . ', PE:' . renderTime($rpend) . ', E:' . renderTime($rjend) . '"><span class="process" style="left:' . $rpleft . 'px;width:' . $rpwidth . 'px">&nbsp;</span><span style="background-color:transparent;z-index:1">' . $jobs->{$jstart}->{'FN'} . '</span></div>';
    $previous_jright = $jleft + $jwidth;
  }
  return $html;
}
# /** renderLine() **/

sub renderTime
{
  my ($seconds) = @_;
  my $time_str = '';
  # determine how many hours
  my $an_hour = 60 * 60;
  my $hours = floor($seconds / $an_hour);
  $seconds = $seconds - ($hours * $an_hour);
  my $a_minute = 60;
  my $minutes = floor($seconds / $a_minute);
  $seconds = $seconds - ($minutes * $a_minute);
  if ($hours > 0)
  {
    $time_str = sprintf('%dh%02dm%02ds', $hours, $minutes, $seconds);
  }
  elsif ($minutes > 0)
  {
    $time_str = sprintf('%dm%02ds', $minutes, $seconds);
  }
  else
  {
    $time_str = $seconds . 's';
  }
  return $time_str;
}