@recaptime-dev's working patches + fork for Phorge, a community fork of Phabricator. (Upstream dev and stable branches are at upstream/main and upstream/stable respectively.) hq.recaptime.dev/wiki/Phorge
phorge phabricator

Add an option to make it easier to debug page hangs

Summary:
Fixes T6044. We've had two cases (both the same install, coincidentally) where pages got hung doing too much data fetching.

When pages hang, we don't get a useful stack trace out of them, since nginx, php-fpm, or PHP eventually terminates things in a non-useful way without any diagnostic information.

The second time (the recent Macros issue) I was able to walk the install through removing limits on nginx, php-fpm, php, and eventually getting a profile by letting the page run for several minutes until the request completed. However, this install is exceptionally technically proficient and this was still a big pain for everyone, and this approach would not have worked if the page actually looped rather than just taking a long time.

Provide `debug.time-limit`, which should give us a better tool for reacting to this situation: by setting it to a small value (like 10), we'll kill the page after 10 seconds with a trace, before nginx/php-fpm/php/etc can kill it uselessly. Hopefully that will be enough information to find the issue (generally, getting a trace has been 95% of the problem in the two cases we've encountered).

Test Plan: Set this option to `3` and added a sleep loop, saw a termination after 3 seconds with a useful trace.

Reviewers: btrahan

Reviewed By: btrahan

Subscribers: csilvers, joshuaspence, epriestley

Maniphest Tasks: T6044

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

+96
+25
src/applications/config/option/PhabricatorDeveloperConfigOptions.php
··· 46 46 "enable this option in production.\n\n". 47 47 "You must enable DarkConsole by setting {{darkconsole.enabled}} ". 48 48 "before this option will have any effect.")), 49 + $this->newOption('debug.time-limit', 'int', null) 50 + ->setSummary( 51 + pht( 52 + 'Limit page execution time to debug hangs.')) 53 + ->setDescription( 54 + pht( 55 + "This option can help debug pages which are taking a very ". 56 + "long time (more than 30 seconds) to render.\n\n". 57 + "If a page is slow to render (but taking less than 30 seconds), ". 58 + "the best tools to use to figure out why it is slow are usually ". 59 + "the DarkConsole service call profiler and XHProf.\n\n". 60 + "However, if a request takes a very long time to return, some ". 61 + "components (like Apache, nginx, or PHP itself) may abort the ". 62 + "request before it finishes. This can prevent you from using ". 63 + "profiling tools to understand page performance in detail.\n\n". 64 + "In these cases, you can use this option to force the page to ". 65 + "abort after a smaller number of seconds (for example, 10), and ". 66 + "dump a useful stack trace. This can provide useful information ". 67 + "about why a page is hanging.\n\n". 68 + "To use this option, set it to a small number (like 10), and ". 69 + "reload a hanging page. The page should exit after 10 seconds ". 70 + "and give you a stack trace.\n\n". 71 + "You should turn this option off (set it to 0) when you are ". 72 + "done with it. Leaving it on creates a small amount of overhead ". 73 + "for all requests, even if they do not hit the time limit.")), 49 74 $this->newOption('debug.stop-on-redirect', 'bool', false) 50 75 ->setBoolOptions( 51 76 array(
+65
support/PhabricatorStartup.php
··· 38 38 final class PhabricatorStartup { 39 39 40 40 private static $startTime; 41 + private static $debugTimeLimit; 41 42 private static $globals = array(); 42 43 private static $capturingOutput; 43 44 private static $rawInput; ··· 223 224 } 224 225 self::$capturingOutput = false; 225 226 return ob_get_clean(); 227 + } 228 + 229 + 230 + /* -( Debug Time Limit )--------------------------------------------------- */ 231 + 232 + 233 + /** 234 + * Set a time limit (in seconds) for the current script. After time expires, 235 + * the script fatals. 236 + * 237 + * This works like `max_execution_time`, but prints out a useful stack trace 238 + * when the time limit expires. This is primarily intended to make it easier 239 + * to debug pages which hang by allowing extraction of a stack trace: set a 240 + * short debug limit, then use the trace to figure out what's happening. 241 + * 242 + * The limit is implemented with a tick function, so enabling it implies 243 + * some accounting overhead. 244 + * 245 + * @param int Time limit in seconds. 246 + * @return void 247 + */ 248 + public static function setDebugTimeLimit($limit) { 249 + self::$debugTimeLimit = $limit; 250 + 251 + static $initialized; 252 + if (!$initialized) { 253 + declare(ticks=1); 254 + register_tick_function(array('PhabricatorStartup', 'onDebugTick')); 255 + } 256 + } 257 + 258 + 259 + /** 260 + * Callback tick function used by @{method:setDebugTimeLimit}. 261 + * 262 + * Fatals with a useful stack trace after the time limit expires. 263 + * 264 + * @return void 265 + */ 266 + public static function onDebugTick() { 267 + $limit = self::$debugTimeLimit; 268 + if (!$limit) { 269 + return; 270 + } 271 + 272 + $elapsed = (microtime(true) - self::getStartTime()); 273 + if ($elapsed > $limit) { 274 + $frames = array(); 275 + foreach (debug_backtrace() as $frame) { 276 + $file = isset($frame['file']) ? $frame['file'] : '-'; 277 + $file = basename($file); 278 + 279 + $line = isset($frame['line']) ? $frame['line'] : '-'; 280 + $class = isset($frame['class']) ? $frame['class'].'->' : null; 281 + $func = isset($frame['function']) ? $frame['function'].'()' : '?'; 282 + 283 + $frames[] = "{$file}:{$line} {$class}{$func}"; 284 + } 285 + 286 + self::didFatal( 287 + "Request aborted by debug time limit after {$limit} seconds.\n\n". 288 + "STACK TRACE\n". 289 + implode("\n", $frames)); 290 + } 226 291 } 227 292 228 293
+6
webroot/index.php
··· 16 16 PhabricatorStartup::loadCoreLibraries(); 17 17 18 18 PhabricatorEnv::initializeWebEnvironment(); 19 + 20 + $debug_time_limit = PhabricatorEnv::getEnvConfig('debug.time-limit'); 21 + if ($debug_time_limit) { 22 + PhabricatorStartup::setDebugTimeLimit($debug_time_limit); 23 + } 24 + 19 25 $show_unexpected_traces = PhabricatorEnv::getEnvConfig( 20 26 'phabricator.developer-mode'); 21 27