Add a "Startup" to DarkConsole

Summary: Ref T8588. It looks like something slow is happening //before// we start DarkConsole. Add some crude reporting to try to narrow it down.

Test Plan: {F743050}

Reviewers: chad

Reviewed By: chad

Maniphest Tasks: T8588

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

src/__phutil_library_map__.php

@@ -286,6 +286,7 @@
     'DarkConsolePlugin' => 'applications/console/plugin/DarkConsolePlugin.php',
     'DarkConsoleRequestPlugin' => 'applications/console/plugin/DarkConsoleRequestPlugin.php',
     'DarkConsoleServicesPlugin' => 'applications/console/plugin/DarkConsoleServicesPlugin.php',
+    'DarkConsoleStartupPlugin' => 'applications/console/plugin/DarkConsoleStartupPlugin.php',
     'DarkConsoleXHProfPlugin' => 'applications/console/plugin/DarkConsoleXHProfPlugin.php',
     'DarkConsoleXHProfPluginAPI' => 'applications/console/plugin/xhprof/DarkConsoleXHProfPluginAPI.php',
     'DatabaseConfigurationProvider' => 'infrastructure/storage/configuration/DatabaseConfigurationProvider.php',
@@ -3912,6 +3913,7 @@
     'DarkConsolePlugin' => 'Phobject',
     'DarkConsoleRequestPlugin' => 'DarkConsolePlugin',
     'DarkConsoleServicesPlugin' => 'DarkConsolePlugin',
+    'DarkConsoleStartupPlugin' => 'DarkConsolePlugin',
     'DarkConsoleXHProfPlugin' => 'DarkConsolePlugin',
     'DarkConsoleXHProfPluginAPI' => 'Phobject',
     'DefaultDatabaseConfigurationProvider' => array(

src/aphront/configuration/AphrontApplicationConfiguration.php

@@ -58,6 +58,7 @@ public function willBuildRequest() {}
    * @phutil-external-symbol class PhabricatorStartup
    */
   public static function runHTTPRequest(AphrontHTTPSink $sink) {
+    PhabricatorStartup::beginStartupPhase('multimeter');
     $multimeter = MultimeterControl::newInstance();
     $multimeter->setEventContext('<http-init>');
     $multimeter->setEventViewer('<none>');
@@ -67,6 +68,7 @@ public static function runHTTPRequest(AphrontHTTPSink $sink) {
     // request object first.
     $write_guard = new AphrontWriteGuard('id');
 
+    PhabricatorStartup::beginStartupPhase('env.init');
     PhabricatorEnv::initializeWebEnvironment();
 
     $multimeter->setSampleRate(
@@ -78,6 +80,7 @@ public static function runHTTPRequest(AphrontHTTPSink $sink) {
     }
 
     // This is the earliest we can get away with this, we need env config first.
+    PhabricatorStartup::beginStartupPhase('log.access');
     PhabricatorAccessLog::init();
     $access_log = PhabricatorAccessLog::getLog();
     PhabricatorStartup::setAccessLog($access_log);
@@ -89,6 +92,11 @@ public static function runHTTPRequest(AphrontHTTPSink $sink) {
       ));
 
     DarkConsoleXHProfPluginAPI::hookProfiler();
+
+    // We just activated the profiler, so we don't need to keep track of
+    // startup phases anymore: it can take over from here.
+    PhabricatorStartup::beginStartupPhase('startup.done');
+
     DarkConsoleErrorLogPluginAPI::registerErrorHandler();
 
     $response = PhabricatorSetupCheck::willProcessRequest();

src/applications/console/plugin/DarkConsoleStartupPlugin.php

@@ -0,0 +1,84 @@
+<?php
+
+final class DarkConsoleStartupPlugin extends DarkConsolePlugin {
+
+  public function getName() {
+    return pht('Startup');
+  }
+
+  public function getDescription() {
+    return pht('Timing information about the startup sequence.');
+  }
+
+  /**
+   * @phutil-external-symbol class PhabricatorStartup
+   */
+  public function generateData() {
+    return PhabricatorStartup::getPhases();
+  }
+
+  public function renderPanel() {
+    $data = $this->getData();
+
+    // Compute the time offset and duration of each startup phase.
+    $prev_key = null;
+    $init = null;
+    $phases = array();
+    foreach ($data as $key => $value) {
+      if ($init === null) {
+        $init = $value;
+      }
+
+      $offset = (int)floor(1000 * ($value - $init));
+
+      $phases[$key] = array(
+        'time' => $value,
+        'offset' => $value - $init,
+      );
+
+
+      if ($prev_key !== null) {
+        $phases[$prev_key]['duration'] = $value - $phases[$prev_key]['time'];
+      }
+      $prev_key = $key;
+    }
+
+    // Render the phases.
+    $rows = array();
+    foreach ($phases as $key => $phase) {
+      $offset_ms = (int)floor(1000 * $phase['offset']);
+
+      if (isset($phase['duration'])) {
+        $duration_us = (int)floor(1000000 * $phase['duration']);
+      } else {
+        $duration_us = null;
+      }
+
+      $rows[] = array(
+        $key,
+        pht('+%s ms', new PhutilNumber($offset_ms)),
+        ($duration_us === null)
+          ? pht('-')
+          : pht('%s us', new PhutilNumber($duration_us)),
+        null,
+      );
+    }
+
+    return id(new AphrontTableView($rows))
+      ->setHeaders(
+        array(
+          pht('Phase'),
+          pht('Offset'),
+          pht('Duration'),
+          null,
+        ))
+      ->setColumnClasses(
+        array(
+          '',
+          'n right',
+          'n right',
+          'wide',
+        ));
+  }
+
+}

src/applications/console/plugin/xhprof/DarkConsoleXHProfPluginAPI.php

@@ -124,23 +124,37 @@ public static function hookProfiler() {
     self::startProfiler();
   }
 
+
+  /**
+   * @phutil-external-symbol class PhabricatorStartup
+   */
   private static function startProfiler() {
+    PhabricatorStartup::beginStartupPhase('profiler.init');
+
     self::includeXHProfLib();
     xhprof_enable();
 
     self::$profilerStarted = true;
     self::$profilerRunning = true;
   }
 
+
+  /**
+   * @phutil-external-symbol class PhabricatorStartup
+   */
   public static function getProfileFilePHID() {
+    if (!self::isProfilerRunning()) {
+      return;
+    }
+
+    PhabricatorStartup::beginStartupPhase('profiler.stop');
     self::stopProfiler();
+    PhabricatorStartup::beginStartupPhase('profiler.done');
+
     return self::$profileFilePHID;
   }
 
   private static function stopProfiler() {
-    if (!self::isProfilerRunning()) {
-      return;
-    }
 
     $data = xhprof_disable();
     $data = @json_encode($data);

src/docs/user/field/darkconsole.diviner

@@ -138,6 +138,25 @@ If the services tab looks fine, and particularly if a page is slow but the
 tool to understand problems in PHP is XHProf.
 
 
+Plugin: Startup
+===============
+
+The "Startup" plugin shows information about startup phases. This information
+can provide insight about performance problems which occur before the profiler
+can start.
+
+Normally, the profiler is the best tool for understanding runtime performance,
+but some work is performed before the profiler starts (for example, loading
+libraries and configuration). If there is a substantial difference between the
+wall time reported by the profiler and the "Entire Page" cost reported by the
+Services tab, the Startup tab can help account for that time.
+
+It is normal for starting the profiler to increase the cost of the page
+somewhat: the profiler itself adds overhead while it is running, and the page
+must do some work after the profiler is stopped to save the profile and
+complete other shutdown operations.
+
+
 Plugin: XHProf
 ==============
 

support/PhabricatorStartup.php

@@ -34,6 +34,7 @@
  * @task apocalypse   In Case Of Apocalypse
  * @task validation   Validation
  * @task ratelimit    Rate Limiting
+ * @task phases       Startup Phase Timers
  */
 final class PhabricatorStartup {
 
@@ -43,6 +44,7 @@ final class PhabricatorStartup {
   private static $capturingOutput;
   private static $rawInput;
   private static $oldMemoryLimit;
+  private static $phases;
 
   // TODO: For now, disable rate limiting entirely by default. We need to
   // iterate on it a bit for Conduit, some of the specific score levels, and
@@ -89,10 +91,14 @@ public static function getRawInput() {
 
 
   /**
+   * @param float Request start time, from `microtime(true)`.
    * @task hook
    */
-  public static function didStartup() {
-    self::$startTime = microtime(true);
+  public static function didStartup($start_time) {
+    self::$startTime = $start_time;
+
+    self::$phases = array();
+
     self::$accessLog = null;
 
     static $registered;
@@ -854,4 +860,58 @@ private static function didRateLimit() {
     exit(1);
   }
 
+
+/* -(  Startup Timers  )----------------------------------------------------- */
+
+
+  /**
+   * Record the beginning of a new startup phase.
+   *
+   * For phases which occur before @{class:PhabricatorStartup} loads, save the
+   * time and record it with @{method:recordStartupPhase} after the class is
+   * available.
+   *
+   * @param string Phase name.
+   * @task phases
+   */
+  public static function beginStartupPhase($phase) {
+    self::recordStartupPhase($phase, microtime(true));
+  }
+
+
+  /**
+   * Record the start time of a previously executed startup phase.
+   *
+   * For startup phases which occur after @{class:PhabricatorStartup} loads,
+   * use @{method:beginStartupPhase} instead. This method can be used to
+   * record a time before the class loads, then hand it over once the class
+   * becomes available.
+   *
+   * @param string Phase name.
+   * @param float Phase start time, from `microtime(true)`.
+   * @task phases
+   */
+  public static function recordStartupPhase($phase, $time) {
+    self::$phases[$phase] = $time;
+  }
+
+
+  /**
+   * Get information about startup phase timings.
+   *
+   * Sometimes, performance problems can occur before we start the profiler.
+   * Since the profiler can't examine these phases, it isn't useful in
+   * understanding their performance costs.
+   *
+   * Instead, the startup process marks when it enters various phases using
+   * @{method:beginStartupPhase}. A later call to this method can retrieve this
+   * information, which can be examined to gain greater insight into where
+   * time was spent. The output is still crude, but better than nothing.
+   *
+   * @task phases
+   */
+  public static function getPhases() {
+    return self::$phases;
+  }
+
 }

webroot/index.php

@@ -1,23 +1,19 @@
 <?php
 
-$phabricator_root = dirname(dirname(__FILE__));
-require_once $phabricator_root.'/support/PhabricatorStartup.php';
-
-// If the preamble script exists, load it.
-$preamble_path = $phabricator_root.'/support/preamble.php';
-if (file_exists($preamble_path)) {
-  require_once $preamble_path;
-}
-
-PhabricatorStartup::didStartup();
+phabricator_startup();
 
 try {
+  PhabricatorStartup::beginStartupPhase('libraries');
   PhabricatorStartup::loadCoreLibraries();
+
+  PhabricatorStartup::beginStartupPhase('purge');
   PhabricatorCaches::destroyRequestCache();
 
+  PhabricatorStartup::beginStartupPhase('sink');
   $sink = new AphrontPHPHTTPSink();
 
   try {
+    PhabricatorStartup::beginStartupPhase('run');
     AphrontApplicationConfiguration::runHTTPRequest($sink);
   } catch (Exception $ex) {
     try {
@@ -36,3 +32,24 @@
 } catch (Exception $ex) {
   PhabricatorStartup::didEncounterFatalException('Core Exception', $ex, false);
 }
+
+function phabricator_startup() {
+  // Load the PhabricatorStartup class itself.
+  $t_startup = microtime(true);
+  $root = dirname(dirname(__FILE__));
+  require_once $root.'/support/PhabricatorStartup.php';
+
+  // If the preamble script exists, load it.
+  $t_preamble = microtime(true);
+  $preamble_path = $root.'/support/preamble.php';
+  if (file_exists($preamble_path)) {
+    require_once $preamble_path;
+  }
+
+  $t_hook = microtime(true);
+  PhabricatorStartup::didStartup($t_startup);
+
+  PhabricatorStartup::recordStartupPhase('startup.init', $t_startup);
+  PhabricatorStartup::recordStartupPhase('preamble', $t_preamble);
+  PhabricatorStartup::recordStartupPhase('hook', $t_hook);
+}