diff --git a/resources/sql/autopatches/20180322.lock.02.wait.sql b/resources/sql/autopatches/20180322.lock.02.wait.sql new file mode 100644 index 0000000000..cba7cc64d0 --- /dev/null +++ b/resources/sql/autopatches/20180322.lock.02.wait.sql @@ -0,0 +1,8 @@ +ALTER TABLE {$NAMESPACE}_repository.repository_pushevent + ADD writeWait BIGINT UNSIGNED; + +ALTER TABLE {$NAMESPACE}_repository.repository_pushevent + ADD readWait BIGINT UNSIGNED; + +ALTER TABLE {$NAMESPACE}_repository.repository_pushevent + ADD hostWait BIGINT UNSIGNED; diff --git a/src/applications/diffusion/protocol/DiffusionRepositoryClusterEngine.php b/src/applications/diffusion/protocol/DiffusionRepositoryClusterEngine.php index c855b6c532..d5ba74a30e 100644 --- a/src/applications/diffusion/protocol/DiffusionRepositoryClusterEngine.php +++ b/src/applications/diffusion/protocol/DiffusionRepositoryClusterEngine.php @@ -315,12 +315,15 @@ final class DiffusionRepositoryClusterEngine extends Phobject { $lock_wait = phutil_units('2 minutes in seconds'); try { + $write_wait_start = microtime(true); + $start = PhabricatorTime::getNow(); $step_wait = 1; while (true) { try { $write_lock->lock((int)floor($step_wait)); + $write_wait_end = microtime(true); break; } catch (PhutilLockException $ex) { $waited = (PhabricatorTime::getNow() - $start); @@ -370,12 +373,14 @@ final class DiffusionRepositoryClusterEngine extends Phobject { 'documentation for instructions.')); } + $read_wait_start = microtime(true); try { $max_version = $this->synchronizeWorkingCopyBeforeRead(); } catch (Exception $ex) { $write_lock->unlock(); throw $ex; } + $read_wait_end = microtime(true); $pid = getmypid(); $hash = Filesystem::readRandomCharacters(12); @@ -394,6 +399,15 @@ final class DiffusionRepositoryClusterEngine extends Phobject { $this->clusterWriteVersion = $max_version; $this->clusterWriteLock = $write_lock; + + $write_wait = ($write_wait_end - $write_wait_start); + $read_wait = ($read_wait_end - $read_wait_start); + + $log = $this->logger; + if ($log) { + $log->writeClusterEngineLogProperty('readWait', $read_wait); + $log->writeClusterEngineLogProperty('writeWait', $write_wait); + } } diff --git a/src/applications/diffusion/protocol/DiffusionRepositoryClusterEngineLogInterface.php b/src/applications/diffusion/protocol/DiffusionRepositoryClusterEngineLogInterface.php index 9b1fe9a506..3e43d72779 100644 --- a/src/applications/diffusion/protocol/DiffusionRepositoryClusterEngineLogInterface.php +++ b/src/applications/diffusion/protocol/DiffusionRepositoryClusterEngineLogInterface.php @@ -3,5 +3,6 @@ interface DiffusionRepositoryClusterEngineLogInterface { public function writeClusterEngineLogMessage($message); + public function writeClusterEngineLogProperty($key, $value); } diff --git a/src/applications/diffusion/ssh/DiffusionGitReceivePackSSHWorkflow.php b/src/applications/diffusion/ssh/DiffusionGitReceivePackSSHWorkflow.php index 91c8238718..400340abeb 100644 --- a/src/applications/diffusion/ssh/DiffusionGitReceivePackSSHWorkflow.php +++ b/src/applications/diffusion/ssh/DiffusionGitReceivePackSSHWorkflow.php @@ -14,6 +14,8 @@ final class DiffusionGitReceivePackSSHWorkflow extends DiffusionGitSSHWorkflow { } protected function executeRepositoryOperations() { + $host_wait_start = microtime(true); + $repository = $this->getRepository(); $viewer = $this->getSSHUser(); $device = AlmanacKeys::getLiveDevice(); @@ -71,6 +73,14 @@ final class DiffusionGitReceivePackSSHWorkflow extends DiffusionGitSSHWorkflow { PhabricatorRepositoryStatusMessage::TYPE_NEEDS_UPDATE, PhabricatorRepositoryStatusMessage::CODE_OKAY); $this->waitForGitClient(); + + $host_wait_end = microtime(true); + + $this->updatePushLogWithTimingInformation( + $this->getClusterEngineLogProperty('writeWait'), + $this->getClusterEngineLogProperty('readWait'), + ($host_wait_end - $host_wait_start)); + } return $err; @@ -89,4 +99,37 @@ final class DiffusionGitReceivePackSSHWorkflow extends DiffusionGitSSHWorkflow { ->execute(); } + private function updatePushLogWithTimingInformation( + $write_wait, + $read_wait, + $host_wait) { + + if ($write_wait !== null) { + $write_wait = (int)(1000000 * $write_wait); + } + + if ($read_wait !== null) { + $read_wait = (int)(1000000 * $read_wait); + } + + if ($host_wait !== null) { + $host_wait = (int)(1000000 * $host_wait); + } + + $identifier = $this->getRequestIdentifier(); + + $event = new PhabricatorRepositoryPushEvent(); + $conn = $event->establishConnection('w'); + + queryfx( + $conn, + 'UPDATE %T SET writeWait = %nd, readWait = %nd, hostWait = %nd + WHERE requestIdentifier = %s', + $event->getTableName(), + $write_wait, + $read_wait, + $host_wait, + $identifier); + } + } diff --git a/src/applications/diffusion/ssh/DiffusionGitSSHWorkflow.php b/src/applications/diffusion/ssh/DiffusionGitSSHWorkflow.php index 6de16e723d..6bc56d767d 100644 --- a/src/applications/diffusion/ssh/DiffusionGitSSHWorkflow.php +++ b/src/applications/diffusion/ssh/DiffusionGitSSHWorkflow.php @@ -4,6 +4,8 @@ abstract class DiffusionGitSSHWorkflow extends DiffusionSSHWorkflow implements DiffusionRepositoryClusterEngineLogInterface { + private $engineLogProperties = array(); + protected function writeError($message) { // Git assumes we'll add our own newlines. return parent::writeError($message."\n"); @@ -14,6 +16,14 @@ abstract class DiffusionGitSSHWorkflow $this->getErrorChannel()->update(); } + public function writeClusterEngineLogProperty($key, $value) { + $this->engineLogProperties[$key] = $value; + } + + protected function getClusterEngineLogProperty($key, $default = null) { + return idx($this->engineLogProperties, $key, $default); + } + protected function identifyRepository() { $args = $this->getArgs(); $path = head($args->getArg('dir')); diff --git a/src/applications/repository/query/PhabricatorRepositoryPushLogSearchEngine.php b/src/applications/repository/query/PhabricatorRepositoryPushLogSearchEngine.php index 5bf2c84aeb..7b626fff32 100644 --- a/src/applications/repository/query/PhabricatorRepositoryPushLogSearchEngine.php +++ b/src/applications/repository/query/PhabricatorRepositoryPushLogSearchEngine.php @@ -98,57 +98,66 @@ final class PhabricatorRepositoryPushLogSearchEngine $viewer = $this->requireViewer(); $fields = array( - $fields[] = id(new PhabricatorIDExportField()) + id(new PhabricatorIDExportField()) ->setKey('pushID') ->setLabel(pht('Push ID')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('unique') ->setLabel(pht('Unique')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('protocol') ->setLabel(pht('Protocol')), - $fields[] = id(new PhabricatorPHIDExportField()) + id(new PhabricatorPHIDExportField()) ->setKey('repositoryPHID') ->setLabel(pht('Repository PHID')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('repository') ->setLabel(pht('Repository')), - $fields[] = id(new PhabricatorPHIDExportField()) + id(new PhabricatorPHIDExportField()) ->setKey('pusherPHID') ->setLabel(pht('Pusher PHID')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('pusher') ->setLabel(pht('Pusher')), - $fields[] = id(new PhabricatorPHIDExportField()) + id(new PhabricatorPHIDExportField()) ->setKey('devicePHID') ->setLabel(pht('Device PHID')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('device') ->setLabel(pht('Device')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('type') ->setLabel(pht('Ref Type')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('name') ->setLabel(pht('Ref Name')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('old') ->setLabel(pht('Ref Old')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('new') ->setLabel(pht('Ref New')), - $fields[] = id(new PhabricatorIntExportField()) + id(new PhabricatorIntExportField()) ->setKey('flags') ->setLabel(pht('Flags')), - $fields[] = id(new PhabricatorStringListExportField()) + id(new PhabricatorStringListExportField()) ->setKey('flagNames') ->setLabel(pht('Flag Names')), - $fields[] = id(new PhabricatorIntExportField()) + id(new PhabricatorIntExportField()) ->setKey('result') ->setLabel(pht('Result')), - $fields[] = id(new PhabricatorStringExportField()) + id(new PhabricatorStringExportField()) ->setKey('resultName') ->setLabel(pht('Result Name')), + id(new PhabricatorIntExportField()) + ->setKey('writeWait') + ->setLabel(pht('Write Wait (us)')), + id(new PhabricatorIntExportField()) + ->setKey('readWait') + ->setLabel(pht('Read Wait (us)')), + id(new PhabricatorIntExportField()) + ->setKey('hostWait') + ->setLabel(pht('Host Wait (us)')), ); if ($viewer->getIsAdmin()) { @@ -228,6 +237,9 @@ final class PhabricatorRepositoryPushLogSearchEngine 'flagNames' => $flag_names, 'result' => $result, 'resultName' => $result_name, + 'writeWait' => $event->getWriteWait(), + 'readWait' => $event->getReadWait(), + 'hostWait' => $event->getHostWait(), ); if ($viewer->getIsAdmin()) { diff --git a/src/applications/repository/storage/PhabricatorRepositoryPushEvent.php b/src/applications/repository/storage/PhabricatorRepositoryPushEvent.php index 369af15635..451f8acda5 100644 --- a/src/applications/repository/storage/PhabricatorRepositoryPushEvent.php +++ b/src/applications/repository/storage/PhabricatorRepositoryPushEvent.php @@ -16,6 +16,9 @@ final class PhabricatorRepositoryPushEvent protected $remoteProtocol; protected $rejectCode; protected $rejectDetails; + protected $writeWait; + protected $readWait; + protected $hostWait; private $repository = self::ATTACHABLE; private $logs = self::ATTACHABLE; @@ -35,6 +38,9 @@ final class PhabricatorRepositoryPushEvent 'remoteProtocol' => 'text32?', 'rejectCode' => 'uint32', 'rejectDetails' => 'text64?', + 'writeWait' => 'uint64?', + 'readWait' => 'uint64?', + 'hostWait' => 'uint64?', ), self::CONFIG_KEY_SCHEMA => array( 'key_repository' => array(