diff --git a/src/__phutil_library_map__.php b/src/__phutil_library_map__.php index d7f747ca13..0942ad73d6 100644 --- a/src/__phutil_library_map__.php +++ b/src/__phutil_library_map__.php @@ -286,6 +286,7 @@ phutil_register_library_map(array( '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 @@ phutil_register_library_map(array( 'DarkConsolePlugin' => 'Phobject', 'DarkConsoleRequestPlugin' => 'DarkConsolePlugin', 'DarkConsoleServicesPlugin' => 'DarkConsolePlugin', + 'DarkConsoleStartupPlugin' => 'DarkConsolePlugin', 'DarkConsoleXHProfPlugin' => 'DarkConsolePlugin', 'DarkConsoleXHProfPluginAPI' => 'Phobject', 'DefaultDatabaseConfigurationProvider' => array( diff --git a/src/aphront/configuration/AphrontApplicationConfiguration.php b/src/aphront/configuration/AphrontApplicationConfiguration.php index 0a33f6f77c..7943b8046d 100644 --- a/src/aphront/configuration/AphrontApplicationConfiguration.php +++ b/src/aphront/configuration/AphrontApplicationConfiguration.php @@ -58,6 +58,7 @@ abstract class AphrontApplicationConfiguration extends Phobject { * @phutil-external-symbol class PhabricatorStartup */ public static function runHTTPRequest(AphrontHTTPSink $sink) { + PhabricatorStartup::beginStartupPhase('multimeter'); $multimeter = MultimeterControl::newInstance(); $multimeter->setEventContext(''); $multimeter->setEventViewer(''); @@ -67,6 +68,7 @@ abstract class AphrontApplicationConfiguration extends Phobject { // request object first. $write_guard = new AphrontWriteGuard('id'); + PhabricatorStartup::beginStartupPhase('env.init'); PhabricatorEnv::initializeWebEnvironment(); $multimeter->setSampleRate( @@ -78,6 +80,7 @@ abstract class AphrontApplicationConfiguration extends Phobject { } // 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 @@ abstract class AphrontApplicationConfiguration extends Phobject { )); 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(); diff --git a/src/applications/console/plugin/DarkConsoleStartupPlugin.php b/src/applications/console/plugin/DarkConsoleStartupPlugin.php new file mode 100644 index 0000000000..4cc166725f --- /dev/null +++ b/src/applications/console/plugin/DarkConsoleStartupPlugin.php @@ -0,0 +1,84 @@ +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', + )); + } + +} diff --git a/src/applications/console/plugin/xhprof/DarkConsoleXHProfPluginAPI.php b/src/applications/console/plugin/xhprof/DarkConsoleXHProfPluginAPI.php index ea2f1bbadb..747ddd2267 100644 --- a/src/applications/console/plugin/xhprof/DarkConsoleXHProfPluginAPI.php +++ b/src/applications/console/plugin/xhprof/DarkConsoleXHProfPluginAPI.php @@ -124,7 +124,13 @@ final class DarkConsoleXHProfPluginAPI extends Phobject { self::startProfiler(); } + + /** + * @phutil-external-symbol class PhabricatorStartup + */ private static function startProfiler() { + PhabricatorStartup::beginStartupPhase('profiler.init'); + self::includeXHProfLib(); xhprof_enable(); @@ -132,15 +138,23 @@ final class DarkConsoleXHProfPluginAPI extends Phobject { 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); diff --git a/src/docs/user/field/darkconsole.diviner b/src/docs/user/field/darkconsole.diviner index d235f6c1e4..a31f0492ae 100644 --- a/src/docs/user/field/darkconsole.diviner +++ b/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 ============== diff --git a/support/PhabricatorStartup.php b/support/PhabricatorStartup.php index fd612f27b0..198cc1b244 100644 --- a/support/PhabricatorStartup.php +++ b/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 @@ final class PhabricatorStartup { /** + * @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 @@ final class PhabricatorStartup { 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; + } + } diff --git a/webroot/index.php b/webroot/index.php index 3e749be0a9..59e5b71075 100644 --- a/webroot/index.php +++ b/webroot/index.php @@ -1,23 +1,19 @@