Speed up tests by running the biggest ones first

Towards the end of a test run, there's typically a period when only
one or a few cores are busy with the last of the tests---the ones that
take a very long time. By sorting the tests according to their
expected runtime and starting the longest-running ones first, we
minimize this effect.

This patch records the runtime in ~/.gtest-parallel-times once all
tests have finished; on subsequent runs, this data is used to start
the longest-running tests first. Speedup varies depending on which
tests are run, but the usual seems to be about 10%, and I haven't
observed a slowdown for any set of tests (though admittedly, my sample
is very modest).

gtest-parallel

diff --git a/gtest-parallel b/gtest-parallel
index 71c0ed6..58d2a67 100755
--- a/gtest-parallel
+++ b/gtest-parallel
@@ -12,11 +12,15 @@
 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
+import cPickle
+import gzip
 import optparse
+import os
 import subprocess
 import sys
 import threading
 import time
+import zlib
 
 stdout_lock = threading.Lock()
 class FilterFormat:
@@ -82,6 +86,52 @@
   def end(self):
     pass
 
+# Record of test runtimes. Has built-in locking.
+class TestTimes(object):
+  def __init__(self, save_file):
+    "Create new object seeded with saved test times from the given file."
+    self.__times = {}  # (test binary, test name) -> runtime in ms
+
+    # Protects calls to record_test_time(); other calls are not
+    # expected to be made concurrently.
+    self.__lock = threading.Lock()
+
+    try:
+      with gzip.GzipFile(save_file, "rb") as f:
+        times = cPickle.load(f)
+    except (EOFError, IOError, cPickle.UnpicklingError, zlib.error):
+      # File doesn't exist, isn't readable, is malformed---whatever.
+      # Just ignore it.
+      return
+
+    # Discard saved times if the format isn't right.
+    if type(times) is not dict:
+      return
+    for ((test_binary, test_name), runtime) in times.items():
+      if (type(test_binary) is not str or type(test_name) is not str
+          or type(runtime) not in {int, long}):
+        return
+
+    self.__times = times
+
+  def get_test_time(self, binary, testname):
+    "Return the last duration for the given test, or 0 if there's no record."
+    return self.__times.get((binary, testname), 0)
+
+  def record_test_time(self, binary, testname, runtime_ms):
+    "Record that the given test ran in the specified number of milliseconds."
+    with self.__lock:
+      self.__times[(binary, testname)] = runtime_ms
+
+  def write_to_file(self, save_file):
+    "Write all the times to file."
+    try:
+      with open(save_file, "wb") as f:
+        with gzip.GzipFile("", "wb", 9, f) as gzf:
+          cPickle.dump(self.__times, gzf, cPickle.HIGHEST_PROTOCOL)
+    except IOError:
+      pass  # ignore errors---saving the times isn't that important
+
 # Remove additional arguments (anything after --).
 additional_args = []
 
@@ -122,6 +172,8 @@
   sys.exit("Unknown output format: " + options.format)
 
 # Find tests.
+save_file = os.path.join(os.path.expanduser("~"), ".gtest-parallel-times")
+times = TestTimes(save_file)
 tests = []
 for test_binary in binaries:
   command = [test_binary]
@@ -155,7 +207,9 @@
       continue
 
     test = test_group + line
-    tests.append((test_binary, command, test))
+    tests.append((times.get_test_time(test_binary, test),
+                  test_binary, test, command))
+tests.sort(reverse=True)
 
 # Repeat tests (-r flag).
 tests *= options.repeat
@@ -164,6 +218,8 @@
 logger.log(str(-1) + ': TESTCNT ' + ' ' + str(len(tests)))
 
 exit_code = 0
+
+# Run the specified job. Returns the elapsed time in milliseconds.
 def run_job((command, job_id, test)):
   begin = time.time()
   sub = subprocess.Popen(command + ['--gtest_filter=' + test] +
@@ -179,10 +235,11 @@
 
   code = sub.wait()
   runtime_ms = int(1000 * (time.time() - begin))
-  logger.log(str(job_id) + ': EXIT ' + str(code) + ' ' + str(runtime_ms))
+  logger.log("%s: EXIT %s %d" % (job_id, code, runtime_ms))
   if code != 0:
     global exit_code
     exit_code = code
+  return runtime_ms
 
 def worker():
   global job_id
@@ -190,14 +247,14 @@
     job = None
     test_lock.acquire()
     if job_id < len(tests):
-      (test_binary, command, test) = tests[job_id]
+      (_, test_binary, test, command) = tests[job_id]
       logger.log(str(job_id) + ': TEST ' + test_binary + ' ' + test)
       job = (command, job_id, test)
     job_id += 1
     test_lock.release()
     if job is None:
       return
-    run_job(job)
+    times.record_test_time(test_binary, test, run_job(job))
 
 def start_daemon(func):
   t = threading.Thread(target=func)
@@ -209,4 +266,5 @@
 
 [t.join() for t in workers]
 logger.end()
+times.write_to_file(save_file)
 sys.exit(exit_code)