diff --git a/src/applications/herald/adapter/HeraldAdapter.php b/src/applications/herald/adapter/HeraldAdapter.php --- a/src/applications/herald/adapter/HeraldAdapter.php +++ b/src/applications/herald/adapter/HeraldAdapter.php @@ -130,6 +130,14 @@ 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()); diff --git a/src/applications/herald/controller/HeraldTranscriptController.php b/src/applications/herald/controller/HeraldTranscriptController.php --- a/src/applications/herald/controller/HeraldTranscriptController.php +++ b/src/applications/herald/controller/HeraldTranscriptController.php @@ -77,6 +77,7 @@ $this->buildTransactionsTranscriptPanel( $object, $xscript), + $this->buildProfilerTranscriptPanel($xscript), ); } @@ -597,4 +598,98 @@ } + 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; + } + } diff --git a/src/applications/herald/engine/HeraldEngine.php b/src/applications/herald/engine/HeraldEngine.php --- a/src/applications/herald/engine/HeraldEngine.php +++ b/src/applications/herald/engine/HeraldEngine.php @@ -16,6 +16,9 @@ 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 @@ ->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 @@ break; } - $match = $this->doesConditionMatch($rule, $condition, $object); + // 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 @@ 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 @@ 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); + } + + } diff --git a/src/applications/herald/storage/transcript/HeraldObjectTranscript.php b/src/applications/herald/storage/transcript/HeraldObjectTranscript.php --- a/src/applications/herald/storage/transcript/HeraldObjectTranscript.php +++ b/src/applications/herald/storage/transcript/HeraldObjectTranscript.php @@ -7,6 +7,7 @@ protected $name; protected $fields; protected $appliedTransactionPHIDs; + protected $profile; public function setPHID($phid) { $this->phid = $phid; @@ -48,6 +49,15 @@ 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;