From f1a588c771f648173e46302bf71543e2f31d8adf Mon Sep 17 00:00:00 2001 From: epriestley Date: Fri, 31 May 2019 07:22:10 -0700 Subject: [PATCH] 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 --- .../herald/adapter/HeraldAdapter.php | 8 + .../controller/HeraldTranscriptController.php | 95 +++++++++++ .../herald/engine/HeraldEngine.php | 151 +++++++++++++++++- .../transcript/HeraldObjectTranscript.php | 10 ++ 4 files changed, 261 insertions(+), 3 deletions(-) diff --git a/src/applications/herald/adapter/HeraldAdapter.php b/src/applications/herald/adapter/HeraldAdapter.php index 69f538afcc..cb8545b71d 100644 --- a/src/applications/herald/adapter/HeraldAdapter.php +++ b/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()); diff --git a/src/applications/herald/controller/HeraldTranscriptController.php b/src/applications/herald/controller/HeraldTranscriptController.php index 60dd6dc6ed..09a23408d3 100644 --- a/src/applications/herald/controller/HeraldTranscriptController.php +++ b/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; + } + } diff --git a/src/applications/herald/engine/HeraldEngine.php b/src/applications/herald/engine/HeraldEngine.php index 2d96532882..9ca72821e7 100644 --- a/src/applications/herald/engine/HeraldEngine.php +++ b/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; } - $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 @@ 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); + } + + } diff --git a/src/applications/herald/storage/transcript/HeraldObjectTranscript.php b/src/applications/herald/storage/transcript/HeraldObjectTranscript.php index 9d331b271e..b5f9aa783f 100644 --- a/src/applications/herald/storage/transcript/HeraldObjectTranscript.php +++ b/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;