Track total time from task creation to task archival

Summary:
Ref T5401. Depends on D20201. Add timestamps to worker tasks to track task creation, and pass that through to archive tasks. This lets us measure the total time the task spent in the queue, not just the duration it was actually running.

Also displays this information in the daemon status console; see screenshot: {F6225726}

Test Plan:
Stopped daemons, ran `bin/search index --all --background` to create lots of tasks, restarted daemons, observed expected values for `dateCreated` and `epochArchived` in the archive worker table.

Also tested the changes to `unarchiveTask` by forcing a search task to permanently fail and then `bin/worker retry`ing it.

Reviewers: epriestley

Reviewed By: epriestley

Subscribers: Korvin, epriestley, PHID-OPKG-gm6ozazyms6q6i22gyam

Maniphest Tasks: T5401

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

Author: phacility-bot

resources/sql/autopatches/20190220.daemon_worker.completed.01.sql

@@ -0,0 +1,2 @@
+ALTER TABLE {$NAMESPACE}_worker.worker_archivetask
+  ADD archivedEpoch INT UNSIGNED NULL;

resources/sql/autopatches/20190220.daemon_worker.completed.02.sql

@@ -0,0 +1,3 @@
+ALTER TABLE {$NAMESPACE}_worker.worker_activetask
+  ADD dateCreated int unsigned NOT NULL,
+  ADD dateModified int unsigned NOT NULL;

src/applications/daemon/controller/PhabricatorDaemonConsoleController.php

@@ -31,6 +31,7 @@ public function handleRequest(AphrontRequest $request) {
         $completed_info[$class] = array(
           'n' => 0,
           'duration' => 0,
+          'queueTime' => 0,
         );
       }
       $completed_info[$class]['n']++;
@@ -41,16 +42,33 @@ public function handleRequest(AphrontRequest $request) {
       // compute utilization.
       $usage_total += $lease_overhead + ($duration / 1000000);
       $usage_start = min($usage_start, $completed_task->getDateModified());
+
+      $date_archived = $completed_task->getArchivedEpoch();
+      $queue_seconds = $date_archived - $completed_task->getDateCreated();
+
+      // Don't measure queue time for tasks that completed in the same
+      // epoch-second they were created in.
+      if ($queue_seconds > 0) {
+        $sec_in_us = phutil_units('1 second in microseconds');
+        $queue_us = $queue_seconds * $sec_in_us;
+        $queue_exclusive_us = $queue_us - $duration;
+        $queue_exclusive_seconds = $queue_exclusive_us / $sec_in_us;
+        $rounded = floor($queue_exclusive_seconds);
+        $completed_info[$class]['queueTime'] += $rounded;
+      }
     }
 
     $completed_info = isort($completed_info, 'n');
 
     $rows = array();
     foreach ($completed_info as $class => $info) {
+      $duration_avg = new PhutilNumber((int)($info['duration'] / $info['n']));
+      $queue_avg = new PhutilNumber((int)($info['queueTime'] / $info['n']));
       $rows[] = array(
         $class,
         number_format($info['n']),
-        pht('%s us', new PhutilNumber((int)($info['duration'] / $info['n']))),
+        pht('%s us', $duration_avg),
+        pht('%s s', $queue_avg),
       );
     }
 
@@ -98,6 +116,7 @@ public function handleRequest(AphrontRequest $request) {
         phutil_tag('em', array(), pht('Queue Utilization (Approximate)')),
         sprintf('%.1f%%', 100 * $used_time),
         null,
+        null,
       );
     }
 
@@ -108,13 +127,15 @@ public function handleRequest(AphrontRequest $request) {
       array(
         pht('Class'),
         pht('Count'),
-        pht('Avg'),
+        pht('Average Duration'),
+        pht('Average Queue Time'),
       ));
     $completed_table->setColumnClasses(
       array(
         'wide',
         'n',
         'n',
+        'n',
       ));
 
     $completed_panel = id(new PHUIObjectBoxView())

src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php

@@ -12,7 +12,6 @@ protected function getConfiguration() {
 
     $config = array(
       self::CONFIG_IDS => self::IDS_COUNTER,
-      self::CONFIG_TIMESTAMPS => false,
       self::CONFIG_KEY_SCHEMA => array(
         'taskClass' => array(
           'columns' => array('taskClass'),
@@ -118,7 +117,9 @@ public function archiveTask($result, $duration) {
       ->setPriority($this->getPriority())
       ->setObjectPHID($this->getObjectPHID())
       ->setResult($result)
-      ->setDuration($duration);
+      ->setDuration($duration)
+      ->setDateCreated($this->getDateCreated())
+      ->setArchivedEpoch(PhabricatorTime::getNow());
 
     // NOTE: This deletes the active task (this object)!
     $archive->save();

src/infrastructure/daemon/workers/storage/PhabricatorWorkerArchiveTask.php

@@ -8,6 +8,7 @@ final class PhabricatorWorkerArchiveTask extends PhabricatorWorkerTask {
 
   protected $duration;
   protected $result;
+  protected $archivedEpoch;
 
   protected function getConfiguration() {
     $parent = parent::getConfiguration();
@@ -22,6 +23,7 @@ protected function getConfiguration() {
     $config[self::CONFIG_COLUMN_SCHEMA] = array(
       'result' => 'uint32',
       'duration' => 'uint64',
+      'archivedEpoch' => 'epoch?',
     ) + $config[self::CONFIG_COLUMN_SCHEMA];
 
     $config[self::CONFIG_KEY_SCHEMA] = array(
@@ -85,6 +87,7 @@ public function unarchiveTask() {
         ->setDataID($this->getDataID())
         ->setPriority($this->getPriority())
         ->setObjectPHID($this->getObjectPHID())
+        ->setDateCreated($this->getDateCreated())
         ->insert();
 
       $this->setDataID(null);