Add timing information for commit hooks to push logs

Summary:
Depends on D19779. Ref T13216. The push logs currently record the "hostWait", which is roughly "locking + subprocess cost". We also record locking separately, so we can figure out "subprocess cost" alone by subtracting the lock costs.

However, the subprocess (normally `git receive-pack`) runs hooks, and we don't have an easy way to figure out how much time was spent doing actual `git` stuff vs spent doing commit hook processing. This would have been useful in diagnosing at least one recent issue.

Track at least a rough hook cost and record it in the push logs.

Test Plan: Pushed to a repository, saw a reasonable hook cost appear in the database table.

Reviewers: amckinley

Reviewed By: amckinley

Subscribers: PHID-OPKG-gm6ozazyms6q6i22gyam

Maniphest Tasks: T13216

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

Author: epriestley

resources/sql/autopatches/20181106.repo.02.hook.sql

@@ -0,0 +1,2 @@
+ALTER TABLE {$NAMESPACE}_repository.repository_pushevent
+  ADD hookWait BIGINT UNSIGNED;

scripts/repository/commit_hook.php

@@ -17,6 +17,8 @@
 // subclasses of PhabricatorConfigSiteSource to read it and build an instance
 // environment.
 
+$hook_start = microtime(true);
+
 if ($argc > 1) {
   $context = $argv[1];
   $context = explode(':', $context, 2);
@@ -35,7 +37,8 @@
   throw new Exception(pht('usage: commit-hook <repository>'));
 }
 
-$engine = new DiffusionCommitHookEngine();
+$engine = id(new DiffusionCommitHookEngine())
+  ->setStartTime($hook_start);
 
 $repository = id(new PhabricatorRepositoryQuery())
   ->setViewer(PhabricatorUser::getOmnipotentUser())

src/applications/diffusion/engine/DiffusionCommitHookEngine.php

@@ -31,6 +31,7 @@ final class DiffusionCommitHookEngine extends Phobject {
   private $mercurialHook;
   private $mercurialCommits = array();
   private $gitCommits = array();
+  private $startTime;
 
   private $heraldViewerProjects;
   private $rejectCode = PhabricatorRepositoryPushLog::REJECT_BROKEN;
@@ -70,6 +71,15 @@ public function getRequestIdentifier() {
     return $this->requestIdentifier;
   }
 
+  public function setStartTime($start_time) {
+    $this->startTime = $start_time;
+    return $this;
+  }
+
+  public function getStartTime() {
+    return $this->startTime;
+  }
+
   public function setSubversionTransactionInfo($transaction, $repository) {
     $this->subversionTransaction = $transaction;
     $this->subversionRepository = $repository;
@@ -1102,11 +1112,15 @@ private function newPushLog() {
   private function newPushEvent() {
     $viewer = $this->getViewer();
 
+    $hook_start = $this->getStartTime();
+    $hook_end = microtime(true);
+
     $event = PhabricatorRepositoryPushEvent::initializeNewEvent($viewer)
       ->setRepositoryPHID($this->getRepository()->getPHID())
       ->setRemoteAddress($this->getRemoteAddress())
       ->setRemoteProtocol($this->getRemoteProtocol())
-      ->setEpoch(PhabricatorTime::getNow());
+      ->setEpoch(PhabricatorTime::getNow())
+      ->setHookWait((int)(1000000 * ($hook_end - $hook_start)));
 
     $identifier = $this->getRequestIdentifier();
     if (strlen($identifier)) {

src/applications/repository/storage/PhabricatorRepositoryPushEvent.php

@@ -19,6 +19,7 @@ final class PhabricatorRepositoryPushEvent
   protected $writeWait;
   protected $readWait;
   protected $hostWait;
+  protected $hookWait;
 
   private $repository = self::ATTACHABLE;
   private $logs = self::ATTACHABLE;
@@ -41,6 +42,7 @@ protected function getConfiguration() {
         'writeWait' => 'uint64?',
         'readWait' => 'uint64?',
         'hostWait' => 'uint64?',
+        'hookWait' => 'uint64?',
       ),
       self::CONFIG_KEY_SCHEMA => array(
         'key_repository' => array(