Add a basic profiler to Herald transcripts

Summary:
Ref T13298. Add a simple profiler as a starting point to catch any egregiously expensive rules or conditions.

This doesn't profile rule actions, so if "Add subscriber" (or whatever) is outrageously expensive it won't show up on the profile. Right now, actions get evaluated inside the Adapter so they're hard to profile. A future change could likely dig them out without too much trouble. I generally expect actions to be less expensive than conditions.

This also can't pin down a //specific// condition being expensive, but if you see that `H123` takes 20s to evaluate you can probably guess that the giant complicated regex is the expensive part.

Test Plan: {F6473407}

Reviewers: amckinley

Reviewed By: amckinley

Maniphest Tasks: T13298

Differential Revision: https://secure.phabricator.com/D20566

src/applications/herald/adapter/HeraldAdapter.php

@@ -130,6 +130,14 @@ abstract class HeraldAdapter extends Phobject {
 
   abstract public function getHeraldName();
 
+  final public function willGetHeraldField($field_key) {
+    // This method is called during rule evaluation, before we engage the
+    // Herald profiler. We make sure we have a concrete implementation so time
+    // spent loading fields out of the classmap is not mistakenly attributed to
+    // whichever field happens to evaluate first.
+    $this->requireFieldImplementation($field_key);
+  }
+
   public function getHeraldField($field_key) {
     return $this->requireFieldImplementation($field_key)
       ->getHeraldFieldValue($this->getObject());

src/applications/herald/controller/HeraldTranscriptController.php

@@ -77,6 +77,7 @@ final class HeraldTranscriptController extends HeraldController {
         $this->buildTransactionsTranscriptPanel(
           $object,
           $xscript),
+        $this->buildProfilerTranscriptPanel($xscript),
       );
     }
 
@@ -597,4 +598,98 @@ final class HeraldTranscriptController extends HeraldController {
   }
 
 
+  private function buildProfilerTranscriptPanel(HeraldTranscript $xscript) {
+    $viewer = $this->getViewer();
+
+    $object_xscript = $xscript->getObjectTranscript();
+
+    $profile = $object_xscript->getProfile();
+
+    // If this is an older transcript without profiler information, don't
+    // show anything.
+    if ($profile === null) {
+      return null;
+    }
+
+    $profile = isort($profile, 'elapsed');
+    $profile = array_reverse($profile);
+
+    $phids = array();
+    foreach ($profile as $frame) {
+      if ($frame['type'] === 'rule') {
+        $phids[] = $frame['key'];
+      }
+    }
+    $handles = $viewer->loadHandles($phids);
+
+    $field_map = HeraldField::getAllFields();
+
+    $rows = array();
+    foreach ($profile as $frame) {
+      $cost = $frame['elapsed'];
+      $cost = 1000000 * $cost;
+      $cost = pht('%sus', new PhutilNumber($cost));
+
+      $type = $frame['type'];
+      switch ($type) {
+        case 'rule':
+          $type_display = pht('Rule');
+          break;
+        case 'field':
+          $type_display = pht('Field');
+          break;
+        default:
+          $type_display = $type;
+          break;
+      }
+
+      $key = $frame['key'];
+      switch ($type) {
+        case 'field':
+          $field_object = idx($field_map, $key);
+          if ($field_object) {
+            $key_display = $field_object->getHeraldFieldName();
+          } else {
+            $key_display = $key;
+          }
+          break;
+        case 'rule':
+          $key_display = $handles[$key]->renderLink();
+          break;
+        default:
+          $key_display = $key;
+          break;
+      }
+
+      $rows[] = array(
+        $type_display,
+        $key_display,
+        $cost,
+        pht('%s', new PhutilNumber($frame['count'])),
+      );
+    }
+
+    $table_view = id(new AphrontTableView($rows))
+      ->setHeaders(
+        array(
+          pht('Type'),
+          pht('What'),
+          pht('Cost'),
+          pht('Count'),
+        ))
+      ->setColumnClasses(
+        array(
+          null,
+          'wide',
+          'right',
+          'right',
+        ));
+
+    $box_view = id(new PHUIObjectBoxView())
+      ->setHeaderText(pht('Profile'))
+      ->setTable($table_view);
+
+    return $box_view;
+  }
+
 }

src/applications/herald/engine/HeraldEngine.php

@@ -16,6 +16,9 @@ final class HeraldEngine extends Phobject {
   private $forbiddenActions = array();
   private $skipEffects = array();
 
+  private $profilerStack = array();
+  private $profilerFrames = array();
+
   public function setDryRun($dry_run) {
     $this->dryRun = $dry_run;
     return $this;
@@ -137,7 +140,8 @@ final class HeraldEngine extends Phobject {
       ->setName($object->getHeraldName())
       ->setType($object->getAdapterContentType())
       ->setFields($this->fieldCache)
-      ->setAppliedTransactionPHIDs($xaction_phids);
+      ->setAppliedTransactionPHIDs($xaction_phids)
+      ->setProfile($this->getProfile());
 
     $this->transcript->setObjectTranscript($object_transcript);
 
@@ -329,7 +333,36 @@ final class HeraldEngine extends Phobject {
           break;
         }
 
+        // Here, we're profiling the cost to match the condition value against
+        // whatever test is configured. Normally, this cost should be very
+        // small (<<1ms) since it amounts to a single comparison:
+        //
+        //   [ Task author ][ is any of ][ alice ]
+        //
+        // However, it may be expensive in some cases, particularly if you
+        // write a rule with a very creative regular expression that backtracks
+        // explosively.
+        //
+        // At time of writing, the "Another Herald Rule" field is also
+        // evaluated inside the matching function. This may be arbitrarily
+        // expensive (it can prompt us to execute any finite number of other
+        // Herald rules), although we'll push the profiler stack appropriately
+        // so we don't count the evaluation time against this rule in the final
+        // profile.
+
+        $caught = null;
+
+        $this->pushProfilerRule($rule);
+        try {
           $match = $this->doesConditionMatch($rule, $condition, $object);
+        } catch (Exception $ex) {
+          $caught = $ex;
+        }
+        $this->popProfilerRule($rule);
+
+        if ($caught) {
+          throw $ex;
+        }
 
         if (!$all && $match) {
           $reason = pht('Any condition matched.');
@@ -421,7 +454,25 @@ final class HeraldEngine extends Phobject {
 
   public function getObjectFieldValue($field) {
     if (!array_key_exists($field, $this->fieldCache)) {
-      $this->fieldCache[$field] = $this->object->getHeraldField($field);
+      $adapter = $this->object;
+
+      $adapter->willGetHeraldField($field);
+
+      $caught = null;
+
+      $this->pushProfilerField($field);
+      try {
+        $value = $adapter->getHeraldField($field);
+      } catch (Exception $ex) {
+        $caught = $ex;
+      }
+      $this->popProfilerField($field);
+
+      if ($caught) {
+        throw $caught;
+      }
+
+      $this->fieldCache[$field] = $value;
     }
 
     return $this->fieldCache[$field];
@@ -637,4 +688,98 @@ final class HeraldEngine extends Phobject {
     return $is_forbidden;
   }
 
+/* -(  Profiler  )----------------------------------------------------------- */
+
+  private function pushProfilerField($field_key) {
+    return $this->pushProfilerStack('field', $field_key);
+  }
+
+  private function popProfilerField($field_key) {
+    return $this->popProfilerStack('field', $field_key);
+  }
+
+  private function pushProfilerRule(HeraldRule $rule) {
+    return $this->pushProfilerStack('rule', $rule->getPHID());
+  }
+
+  private function popProfilerRule(HeraldRule $rule) {
+    return $this->popProfilerStack('rule', $rule->getPHID());
+  }
+
+  private function pushProfilerStack($type, $key) {
+    $this->profilerStack[] = array(
+      'type' => $type,
+      'key' => $key,
+      'start' => microtime(true),
+    );
+
+    return $this;
+  }
+
+  private function popProfilerStack($type, $key) {
+    if (!$this->profilerStack) {
+      throw new Exception(
+        pht(
+          'Unable to pop profiler stack: profiler stack is empty.'));
+    }
+
+    $frame = last($this->profilerStack);
+    if (($frame['type'] !== $type) || ($frame['key'] !== $key)) {
+      throw new Exception(
+        pht(
+          'Unable to pop profiler stack: expected frame of type "%s" with '.
+          'key "%s", but found frame of type "%s" with key "%s".',
+          $type,
+          $key,
+          $frame['type'],
+          $frame['key']));
+    }
+
+    // Accumulate the new timing information into the existing profile. If this
+    // is the first time we've seen this particular rule or field, we'll
+    // create a new empty frame first.
+
+    $elapsed = microtime(true) - $frame['start'];
+    $frame_key = sprintf('%s/%s', $type, $key);
+
+    if (!isset($this->profilerFrames[$frame_key])) {
+      $current = array(
+        'type' => $type,
+        'key' => $key,
+        'elapsed' => 0,
+        'count' => 0,
+      );
+    } else {
+      $current = $this->profilerFrames[$frame_key];
+    }
+
+    $current['elapsed'] += $elapsed;
+    $current['count']++;
+
+    $this->profilerFrames[$frame_key] = $current;
+
+    array_pop($this->profilerStack);
+  }
+
+  private function getProfile() {
+    if ($this->profilerStack) {
+      $frame = last($this->profilerStack);
+      $frame_type = $frame['type'];
+      $frame_key = $frame['key'];
+      $frame_count = count($this->profilerStack);
+
+      throw new Exception(
+        pht(
+          'Unable to retrieve profile: profiler stack is not empty. The '.
+          'stack has %s frame(s); the final frame has type "%s" and key '.
+          '"%s".',
+          new PhutilNumber($frame_count),
+          $frame_type,
+          $frame_key));
+    }
+
+    return array_values($this->profilerFrames);
+  }
+
+
 }

src/applications/herald/storage/transcript/HeraldObjectTranscript.php

@@ -7,6 +7,7 @@ final class HeraldObjectTranscript extends Phobject {
   protected $name;
   protected $fields;
   protected $appliedTransactionPHIDs;
+  protected $profile;
 
   public function setPHID($phid) {
     $this->phid = $phid;
@@ -48,6 +49,15 @@ final class HeraldObjectTranscript extends Phobject {
     return $this->fields;
   }
 
+  public function setProfile(array $profile) {
+    $this->profile = $profile;
+    return $this;
+  }
+
+  public function getProfile() {
+    return $this->profile;
+  }
+
   public function setAppliedTransactionPHIDs($phids) {
     $this->appliedTransactionPHIDs = $phids;
     return $this;