From abc26aa96f4cfa31ecf6ffda83e4c3a948f21eb4 Mon Sep 17 00:00:00 2001 From: Austin McKinley Date: Wed, 20 Feb 2019 10:24:33 -0800 Subject: [PATCH] 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 --- .../20190220.daemon_worker.completed.01.sql | 2 ++ .../20190220.daemon_worker.completed.02.sql | 3 +++ .../PhabricatorDaemonConsoleController.php | 25 +++++++++++++++++-- .../storage/PhabricatorWorkerActiveTask.php | 5 ++-- .../storage/PhabricatorWorkerArchiveTask.php | 3 +++ 5 files changed, 34 insertions(+), 4 deletions(-) create mode 100644 resources/sql/autopatches/20190220.daemon_worker.completed.01.sql create mode 100644 resources/sql/autopatches/20190220.daemon_worker.completed.02.sql diff --git a/resources/sql/autopatches/20190220.daemon_worker.completed.01.sql b/resources/sql/autopatches/20190220.daemon_worker.completed.01.sql new file mode 100644 index 0000000000..37f5a89bba --- /dev/null +++ b/resources/sql/autopatches/20190220.daemon_worker.completed.01.sql @@ -0,0 +1,2 @@ +ALTER TABLE {$NAMESPACE}_worker.worker_archivetask + ADD archivedEpoch INT UNSIGNED NULL; diff --git a/resources/sql/autopatches/20190220.daemon_worker.completed.02.sql b/resources/sql/autopatches/20190220.daemon_worker.completed.02.sql new file mode 100644 index 0000000000..f0040576a9 --- /dev/null +++ b/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; diff --git a/src/applications/daemon/controller/PhabricatorDaemonConsoleController.php b/src/applications/daemon/controller/PhabricatorDaemonConsoleController.php index a70cde04c4..421008082f 100644 --- a/src/applications/daemon/controller/PhabricatorDaemonConsoleController.php +++ b/src/applications/daemon/controller/PhabricatorDaemonConsoleController.php @@ -31,6 +31,7 @@ final class PhabricatorDaemonConsoleController $completed_info[$class] = array( 'n' => 0, 'duration' => 0, + 'queueTime' => 0, ); } $completed_info[$class]['n']++; @@ -41,16 +42,33 @@ final class PhabricatorDaemonConsoleController // 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 @@ final class PhabricatorDaemonConsoleController phutil_tag('em', array(), pht('Queue Utilization (Approximate)')), sprintf('%.1f%%', 100 * $used_time), null, + null, ); } @@ -108,13 +127,15 @@ final class PhabricatorDaemonConsoleController 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()) diff --git a/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php b/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php index b6bd462df7..7139e39ac3 100644 --- a/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php +++ b/src/infrastructure/daemon/workers/storage/PhabricatorWorkerActiveTask.php @@ -12,7 +12,6 @@ final class PhabricatorWorkerActiveTask extends PhabricatorWorkerTask { $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 @@ final class PhabricatorWorkerActiveTask extends PhabricatorWorkerTask { ->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(); diff --git a/src/infrastructure/daemon/workers/storage/PhabricatorWorkerArchiveTask.php b/src/infrastructure/daemon/workers/storage/PhabricatorWorkerArchiveTask.php index 0062d07a84..25a453b47b 100644 --- a/src/infrastructure/daemon/workers/storage/PhabricatorWorkerArchiveTask.php +++ b/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 @@ final class PhabricatorWorkerArchiveTask extends PhabricatorWorkerTask { $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 @@ final class PhabricatorWorkerArchiveTask extends PhabricatorWorkerTask { ->setDataID($this->getDataID()) ->setPriority($this->getPriority()) ->setObjectPHID($this->getObjectPHID()) + ->setDateCreated($this->getDateCreated()) ->insert(); $this->setDataID(null);