Record lock timing information on PushEvents

Summary:
Depends on D19249. Ref T13109. Add timing information to the `PushEvent`:

  - `writeWait`: Time spent waiting for a write lock.
  - `readWait`: Time spent waiting for a read lock.
  - `hostWait`: Roughly, total time spent on the leaf node.

The primary goal here is to see if `readWait` is meaningful in the wild. If it is, that motivates smarter routing, and the value of smarter routing can be demonstrated by looking for a reduction in read wait times.

Test Plan: Pushed some stuff, saw reasonable timing values in the table. Saw timing information in "Export Data".

Maniphest Tasks: T13109

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

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;

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);
+    }
   }
 
 

src/applications/diffusion/protocol/DiffusionRepositoryClusterEngineLogInterface.php

@@ -3,5 +3,6 @@
 interface DiffusionRepositoryClusterEngineLogInterface {
 
   public function writeClusterEngineLogMessage($message);
+  public function writeClusterEngineLogProperty($key, $value);
 
 }

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);
+  }
+
 }

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'));

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()) {

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(