From 2892c6ef1a2a9f7354342093ac4f30871b7d3b6f Mon Sep 17 00:00:00 2001
From: James Ide <ide+github@jameside.com>
Date: Sun, 3 Jul 2011 23:31:14 -0700
Subject: [PATCH] Have Arcanist record how much of my life was spent running
 each unit test

Summary:
Keeping unit tests speedy keeps them useful since people actually won't mind
running them. This diff records the time taken by each test and displays it nice
and colorized. Really, I just want to discourage non-unit tests from making
their way into ##__tests__##.

Some thoughts:

 - The "acceptableness" times are subjective but if dependencies are properly
mocked the times seem to be ok. Integration tests that make network requests to
third-party endpoints and pull in megabytes of data will not survive. This is a
good thing.
 - Fast tests get a gold star, encouraging small tests. I am sorry that the star
does not sparkle.
 - There is no way for a programmer to admit that their test is going to be slow
in some cases. They will be shamed with red text for the life of their test.
 - It might be confusing that fast but failing tests get green text and maybe a
gold star.

Test Plan: Ran some of the unit tests within Arcanist and libphutil. See
https://secure.phabricator.com/file/view/PHID-FILE-cdd3c94c219e0fd7470b/ for
sample output.
Reviewed By: epriestley
Reviewers: epriestley
CC: aran, epriestley
Differential Revision: 588
---
 .../testcase/ArcanistPhutilTestCase.php       |  4 ++
 src/unit/result/ArcanistUnitTestResult.php    | 10 +++++
 src/workflow/unit/ArcanistUnitWorkflow.php    | 43 ++++++++++++++++++-
 3 files changed, 56 insertions(+), 1 deletion(-)

diff --git a/src/unit/engine/phutil/testcase/ArcanistPhutilTestCase.php b/src/unit/engine/phutil/testcase/ArcanistPhutilTestCase.php
index 6f82dbfd..59cc7bc6 100644
--- a/src/unit/engine/phutil/testcase/ArcanistPhutilTestCase.php
+++ b/src/unit/engine/phutil/testcase/ArcanistPhutilTestCase.php
@@ -28,6 +28,7 @@
 abstract class ArcanistPhutilTestCase {
 
   private $runningTest;
+  private $testStartTime;
   private $results = array();
 
 
@@ -162,6 +163,7 @@ abstract class ArcanistPhutilTestCase {
     $result = new ArcanistUnitTestResult();
     $result->setName($this->runningTest);
     $result->setResult(ArcanistUnitTestResult::RESULT_FAIL);
+    $result->setDuration(microtime(true) - $this->testStartTime);
     $result->setUserData($reason);
     $this->results[] = $result;
   }
@@ -179,6 +181,7 @@ abstract class ArcanistPhutilTestCase {
     $result = new ArcanistUnitTestResult();
     $result->setName($this->runningTest);
     $result->setResult(ArcanistUnitTestResult::RESULT_PASS);
+    $result->setDuration(microtime(true) - $this->testStartTime);
     $result->setUserData($reason);
     $this->results[] = $result;
   }
@@ -206,6 +209,7 @@ abstract class ArcanistPhutilTestCase {
       $name = $method->getName();
       if (preg_match('/^test/', $name)) {
         $this->runningTest = $name;
+        $this->testStartTime = microtime(true);
 
         try {
           $this->willRunOneTest($name);
diff --git a/src/unit/result/ArcanistUnitTestResult.php b/src/unit/result/ArcanistUnitTestResult.php
index 426f44aa..e2d63366 100644
--- a/src/unit/result/ArcanistUnitTestResult.php
+++ b/src/unit/result/ArcanistUnitTestResult.php
@@ -33,6 +33,7 @@ class ArcanistUnitTestResult {
   private $namespace;
   private $name;
   private $result;
+  private $duration;
   private $userData;
 
   public function setName($name) {
@@ -53,6 +54,15 @@ class ArcanistUnitTestResult {
     return $this->result;
   }
 
+  public function setDuration($duration) {
+    $this->duration = $duration;
+    return $this;
+  }
+
+  public function getDuration() {
+    return $this->duration;
+  }
+
   public function setUserData($user_data) {
     $this->userData = $user_data;
     return $this;
diff --git a/src/workflow/unit/ArcanistUnitWorkflow.php b/src/workflow/unit/ArcanistUnitWorkflow.php
index cc16239a..d6c14a0a 100644
--- a/src/workflow/unit/ArcanistUnitWorkflow.php
+++ b/src/workflow/unit/ArcanistUnitWorkflow.php
@@ -132,7 +132,11 @@ EOTEXT
         $unresolved[] = $result;
       } else {
         if ($this->engine->shouldEchoTestResults()) {
-          echo '  '.$status_codes[$result_code].' '.$result->getName()."\n";
+          echo '  '.$status_codes[$result_code];
+          if ($result_code == ArcanistUnitTestResult::RESULT_PASS) {
+            echo ' '.self::formatTestDuration($result->getDuration());
+          }
+          echo ' '.$result->getName()."\n";
         }
         if ($result_code != ArcanistUnitTestResult::RESULT_PASS) {
           if ($this->engine->shouldEchoTestResults()) {
@@ -179,4 +183,41 @@ EOTEXT
     }
   }
 
+  private static function formatTestDuration($seconds) {
+    // Very carefully define inclusive upper bounds on acceptable unit test
+    // durations. Times are in milliseconds and are in increasing order.
+    $acceptableness = array(
+      50   => "<fg:green>%s</fg><fg:yellow>\xE2\x98\x85</fg> ",
+      200  => '<fg:green>%s</fg>  ',
+      500  => '<fg:yellow>%s</fg>  ',
+      INF  => '<fg:red>%s</fg>  ',
+    );
+
+    $milliseconds = $seconds * 1000;
+    $duration = self::formatTime($seconds);
+    foreach ($acceptableness as $upper_bound => $formatting) {
+      if ($milliseconds <= $upper_bound) {
+        return phutil_console_format($formatting, $duration);
+      }
+    }
+    return phutil_console_format(end($acceptableness), $duration);
+  }
+
+  private static function formatTime($seconds) {
+    if ($seconds >= 60) {
+      $minutes = floor($seconds / 60);
+      return sprintf('%dm%02ds', $minutes, round($seconds % 60));
+    }
+
+    if ($seconds >= 1) {
+      return sprintf('%4.1fs', $seconds);
+    }
+
+    $milliseconds = $seconds * 1000;
+    if ($milliseconds >= 1) {
+      return sprintf('%3dms', round($milliseconds));
+    }
+
+    return ' <1ms';
+  }
 }