Changeset 28665 for gs2-extensions/parallel-building/trunk/src

Timestamp:

2013-11-21T13:35:52+13:00 (10 years ago)

Author:

jmt12

Message:

Latest changes to workaround resumed syscalls massive duration problem

File:

• gs2-extensions/parallel-building/trunk/src/bin/script/import_with_io_metric.pl (modified) (18 diffs)

gs2-extensions/parallel-building/trunk/src/bin/script/import_with_io_metric.pl

@@ -24 +24 @@
 # strace_analyzer.pl would use
 print " * Initializing... Done\n";
+our $strace_flags = '-f -q -s 256 -T -ttt';
 our $io_function_list = {
                          'access'=>1,
@@ -58 +59 @@
                          'write'=>1
                         };
-
 my $start_time = [gettimeofday()];
 my $collection = '';
 my $debug = 0;
 my $flush_delay = 3;
+
 GetOptions ('collection=s' => \$collection,
             'debug' => \$debug,
             'flushdelay=i' => \$flush_delay)
 or &printUsage('Invalid or missing argument');
+
 if (!defined $collection || $collection eq '')
 {
@@ -88 +90 @@
 print " * Running baseline collection import... ";
 my $dummy_dir = tempdir( CLEANUP => 1);
-my $command1 = 'time -p strace -f -q -T -ttt -s 4096 import.pl -removeold -importdir "' . $dummy_dir .'" "' . $collection . '" 2>&1 1>/dev/null';
+my $command1 = 'strace ' . $strace_flags . ' import.pl -removeold -importdir "' . $dummy_dir .'" "' . $collection . '" 2>&1';
 my $debug_path1 = '';
 if ($debug)
 {
-  $debug_path1 = $collection_path . '/debug-dummy.csv';
-}
-my ($baseline_duration, $baseline_io, $baseline_cpu) = &parseStrace($command1, $collection_path, $debug_path1);
+  $debug_path1 = $collection_path . '/debug-baseline.tsv';
+}
+my ($baseline_duration, $baseline_io, $baseline_misc) = &parseStrace($command1, $collection_path, $debug_path1);
 print "Done\n";
 print '   - Duration:      ' . sprintf('%0.6f', $baseline_duration) . " seconds\n";
-print '   - I/O Duration:  ' . sprintf('%0.6f', $baseline_io) . " seconds\n";
+print '   - SysCall Time:  ' . sprintf('%0.6f', $baseline_io + $baseline_misc) . " seconds\n";
+print '   - SysCall Prct:  ' . sprintf('%d', (($baseline_io + $baseline_misc) / $baseline_duration) * 100) . "%\n";
+print '   - I/O Time:      ' . sprintf('%0.6f', $baseline_io) . " seconds\n";
 print '   - I/O Percent:   ' . sprintf('%d', ($baseline_io / $baseline_duration) * 100) . "%\n";
 if ($debug)
 {
-  print "   - See 'debug-dummy.csv' for raw data\n";
+  print "   - See 'debug-baseline.tsv' for raw data\n";
 }
 print "\n";
-exit;
 
 # 3. Run normal import command within strace reading output line by line
@@ -110 +113 @@
 &flushDiskCache($flush_delay);
 print " * Running import and tracking I/O metrics... ";
-my $command2 = 'strace -f -q -T -ttt -s 256 import.pl -removeold "' . $collection . '" 2>&1';
+my $command2 = 'strace ' . $strace_flags . ' import.pl -removeold "' . $collection . '" 2>&1';
 my $debug_path2 = '';
 if ($debug)
 {
-  $debug_path2 = $collection_path . '/debug-import.csv';
-}
-my ($duration_import, $duration_io, $duration_cpu, $import_complete, $docs_found, $docs_processed) = &parseStrace($command2, $collection_path, $debug_path2);
+  $debug_path2 = $collection_path . '/debug-import.tsv';
+}
+my ($duration_import, $duration_io, $duration_misc, $import_complete, $docs_found, $docs_processed) = &parseStrace($command2, $collection_path, $debug_path2);
 print "Done\n";
 print '   - Import?        ' . ( $import_complete ? 'Completed' : 'Failed') . "\n";
@@ -122 +125 @@
 print '   - Processed:     ' . $docs_processed . ' document' . (($docs_processed > 1) ? 's' : '') . "\n";
 print '   - Duration:      ' . sprintf('%0.6f', $duration_import) . " seconds\n";
+print '   - SysCall Time:  ' . sprintf('%0.6f', $duration_io + $duration_misc) . " seconds\n";
+print '   - SysCall Prct:  ' . sprintf('%d', (($duration_io + $duration_misc) / $duration_import) * 100) . "%\n";
 print '   - I/O Duration:  ' . sprintf('%0.6f', $duration_io) . " seconds\n";
 print '   - I/O Percent:   ' . sprintf('%d', ($duration_io / $duration_import) * 100) . "%\n";
@@ -128 +133 @@
 if ($debug)
 {
-  print "   - See 'debug-import.csv' for raw data\n";
+  print "   - See 'debug-import.tsv' for raw data\n";
 }
 print "\n";
@@ -237 +242 @@
   my $end_timestamp = 0;
   my $io_duration = 0;
-  my $cpu_duration = 0;
+  my $misc_duration = 0;
   my $import_complete = 0;
   my $documents_found = 0;
@@ -258 +263 @@
   if ($debug_path)
   {
-    open(DEBUGOUT, '>:utf8', $debug_path) or die('Error! Failed to open file for writing: '  . $logs_path . '/' . $debug);
-    print DEBUGOUT "TIMESTAMP,PID,SYSCALL,DURATION,TOTALIO,TOTALCPU,ARGS,RESULT\n";
+    open(TSVOUT, '>:utf8', $debug_path) or die('Error! Failed to open file for writing: '  . $logs_path . '/' . $debug);
+    print TSVOUT "TIMESTAMP\tPID\tSYSCALL\tELAPSED\tTOTALIO\tTOTALMISC\tARGS\tRESULT\n";
   }
 
@@ -265 +270 @@
   {
     my $pid = 0;
-    my $line;
-    while ($line = <GSI>)
+    my $line = <GSI>;
+    while ($line)
     {
+      my $next_line = <GSI>;
       if ($logging_enabled)
       {
@@ -277 +283 @@
       while ($line !~ /<unfinished \.\.\.>/ && $line !~ /SIG/ && $line =~ /\(/ && $line !~ /\)\s+=/)
       {
-        my $new_line = '';
-        if ($new_line = <GSI>)
-        {
-          $line .= ' ' . $new_line;
+        $line .= ' ' . $next_line;
+        if ($next_line = <GSI>)
+        {
         }
         else
@@ -289 +294 @@
       }
       # detect and remove any PID information to make the rest of parsing easier
-      if ($line =~ /^\[pid (\d+)\]\s+(.*)$/s)
+      if ($line =~ /^\[pid\s+(\d+)\]\s+(.*)$/s)
       {
         my $new_pid = $1;
@@ -325 +330 @@
           }
         }
-        $line = $timestamp . ' ' . $syscall . '(' . $args_prefix . ' ' . $args_suffix . ') = ' . $result . ' <' . $duration . '>';
+
+        # Time for a hack - duration is highly dubious for suspended
+        # syscalls. It typically includes the total walltime spent doing
+        # anything between when the 'unfinished' and the 'resumed'... time that
+        # is already accounted for in other parsed syscalls.  What I'll do is
+        # limit the resumed calls duration to, at most, the time difference
+        # between this syscall and the next. This is highly inaccurate, of
+        # course, as it includes time spent in userspace but is significantly
+        # better than a elasped duration several times longer than the syscall
+        # actually took.
+        if ($next_line =~ /^.*?(\d+\.\d+)/)
+        {
+          my $next_timestamp = $1;
+          my $timestamp_duration = $next_timestamp - $timestamp;
+          if ($duration > $timestamp_duration)
+          {
+            #rint "[resume: elapsed longer than duration... fudging] ";
+            $duration = $timestamp_duration;
+          }
+        }
+
+        $line = $timestamp . ' ' . $syscall . '(' . $args_prefix . ' ' . $args_suffix . ') = ' . $result . ' <' . sprintf('%0.6f', $duration) . '>';
       }
 
@@ -346 +372 @@
       }
       # - processes announce detachments and resumptions - maybe this explains
-      # why wait4's keep chaning
+      # why wait4's keep chaning (-q should shut these up)
       elsif ($line =~ /^Process (\d+) (detached|resumed)/)
       {
@@ -353 +379 @@
       }
       # - exit_group never has a duration
-      elsif ($line =~ /^(\d+\.\d+)\s+exit_group\(0\)\s+=\s+\?$/)
+      elsif ($line =~ /^(\d+\.\d+)\s+exit_group\((\d+)\)\s+=\s+\?$/)
       {
         my $timestamp = $1;
+        my $exit_value = $2;
         $end_timestamp = $timestamp;
         if ($debug)
         {
-          print DEBUGOUT $timestamp . ',' . $pid . ',"exit_group",0,' . $io_duration . ',' . $cpu_duration . ",\"0\",\"\"\n";
+          print TSVOUT sprintf("%0.6f", ($timestamp - $start_timestamp)) . "\t";
+          print TSVOUT $pid . "\t";
+          print TSVOUT "exit_group\t";
+          print TSVOUT "0.000000\t";
+          print TSVOUT sprintf("%0.6f", $misc_duration) . "\t";
+          print TSVOUT sprintf("%0.6f", $io_duration) . "\t";
+          print TSVOUT $exit_value . "\t";
+          print TSVOUT "?\n";
         }
       }
@@ -389 +423 @@
         else
         {
-          $cpu_duration += $duration;
+          $misc_duration += $duration;
           ##print "[$syscall]";
         }
@@ -417 +451 @@
         if ($debug)
         {
-          $args =~ s/\"/&quot;/g;
           $args =~ s/\r?\n//g;
-          print DEBUGOUT $timestamp . ',' . $pid . ',"' . $syscall . '",' . $duration . ',' . $io_duration . ',' . $cpu_duration . ',"' . $args . '","' . $result . "\"\n";
+          print TSVOUT sprintf("%0.6f", ($timestamp - $start_timestamp)) . "\t";
+          print TSVOUT $pid . "\t";
+          print TSVOUT $syscall . "\t";
+          print TSVOUT sprintf("%0.6f", $duration) . "\t";
+          print TSVOUT sprintf("%0.6f", $misc_duration) . "\t";
+          print TSVOUT sprintf("%0.6f", $io_duration) . "\t";
+          print TSVOUT $args . "\t";
+          print TSVOUT $result . "\n";
         }
       }
@@ -427 +467 @@
         print "\n\nUnparsed: |" . $line . "|\n\n";
       }
+      # Move on to the next line... (may be undef)
+      $line = $next_line;
     }
   }
@@ -440 +482 @@
   if ($debug_path)
   {
-    close(DEBUGOUT);
+    close(TSVOUT);
   }
   my $cmd_duration = $end_timestamp - $start_timestamp;
-  return ($cmd_duration, $io_duration, $cpu_duration, $import_complete, $documents_found, $documents_processed);
+  return ($cmd_duration, $io_duration, $misc_duration, $import_complete, $documents_found, $documents_processed);
 }
 # parseStrace()