From b12e92e6e2dd6b0ec90b88c68fcf1a2b84db4fa7 Mon Sep 17 00:00:00 2001
From: epriestley <git@epriestley.com>
Date: Tue, 6 Nov 2018 14:51:08 -0800
Subject: [PATCH] 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
---
 .../sql/autopatches/20181106.repo.02.hook.sql    |  2 ++
 scripts/repository/commit_hook.php               |  5 ++++-
 .../engine/DiffusionCommitHookEngine.php         | 16 +++++++++++++++-
 .../storage/PhabricatorRepositoryPushEvent.php   |  2 ++
 4 files changed, 23 insertions(+), 2 deletions(-)
 create mode 100644 resources/sql/autopatches/20181106.repo.02.hook.sql

diff --git a/resources/sql/autopatches/20181106.repo.02.hook.sql b/resources/sql/autopatches/20181106.repo.02.hook.sql
new file mode 100644
index 0000000000..be06923044
--- /dev/null
+++ b/resources/sql/autopatches/20181106.repo.02.hook.sql
@@ -0,0 +1,2 @@
+ALTER TABLE {$NAMESPACE}_repository.repository_pushevent
+  ADD hookWait BIGINT UNSIGNED;
diff --git a/scripts/repository/commit_hook.php b/scripts/repository/commit_hook.php
index 64b7b0ec24..df49aa7b00 100755
--- a/scripts/repository/commit_hook.php
+++ b/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 @@ if ($argc < 2) {
   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())
diff --git a/src/applications/diffusion/engine/DiffusionCommitHookEngine.php b/src/applications/diffusion/engine/DiffusionCommitHookEngine.php
index 59fb4b5e12..d22635e859 100644
--- a/src/applications/diffusion/engine/DiffusionCommitHookEngine.php
+++ b/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 @@ final class DiffusionCommitHookEngine extends Phobject {
     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 @@ final class DiffusionCommitHookEngine extends Phobject {
   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)) {
diff --git a/src/applications/repository/storage/PhabricatorRepositoryPushEvent.php b/src/applications/repository/storage/PhabricatorRepositoryPushEvent.php
index 682b367926..ac97aa2bcf 100644
--- a/src/applications/repository/storage/PhabricatorRepositoryPushEvent.php
+++ b/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 @@ final class PhabricatorRepositoryPushEvent
         'writeWait' => 'uint64?',
         'readWait' => 'uint64?',
         'hostWait' => 'uint64?',
+        'hookWait' => 'uint64?',
       ),
       self::CONFIG_KEY_SCHEMA => array(
         'key_repository' => array(