diff --git a/README.md b/README.md index fc149ba7d..c2b225ce4 100644 --- a/README.md +++ b/README.md @@ -7,11 +7,11 @@ uses Mysql and Sphinx, but work is under way to replace those with Postgresql. ## Gazelle Runtime Dependencies -* [PHP 8.2.13+](https://www.php.net/) (required) +* [PHP 8.4.6+](https://www.php.net/) (required) * [nginx](http://wiki.nginx.org/Main) (required) * [nodeJS 20+](https://nodejs.org/en/) (required) * [memcached](http://memcached.org/) (required) -* [sphinx 2.1.1 or newer](http://sphinxsearch.com/) (required) +* [sphinx 2.2.1 or newer](http://sphinxsearch.com/) (required) * [ocelot](https://github.com/OPSnet/Ocelot) (optional) ## Logchecker diff --git a/app/Debug.php b/app/Debug.php index 3f582af09..6617a60cf 100644 --- a/app/Debug.php +++ b/app/Debug.php @@ -5,10 +5,6 @@ namespace Gazelle; use Gazelle\Util\{Irc, Time}; class Debug { - protected const MAX_TIME = 20000; - protected const MAX_ERRORS = 0; //Maxmimum errors, warnings, notices we will allow in a page - protected const MAX_MEMORY = 80 * 1024 * 1024; //Maximum memory used per pageload - protected static int $caseCount = 0; protected static array $Errors = []; protected static array $markList = []; @@ -21,10 +17,15 @@ class Debug { ) { $this->epochStart = microtime(true); $this->cpuStart = $this->cpuElapsed(); - error_reporting(E_WARNING | E_ERROR | E_PARSE); set_error_handler($this->errorHandler(...)); } + public function flush(): int { + $cleared = count(self::$Errors); + self::$Errors = []; + return $cleared; + } + public function epochStart(): float { return $this->epochStart; } @@ -33,42 +34,27 @@ class Debug { return microtime(true) - $this->epochStart(); } - public function profile(User $user, string $document, string $Automatic = ''): bool { - $Reason = []; - - if (!empty($Automatic)) { - $Reason[] = $Automatic; - } - - $Micro = $this->duration() * 1000; - if ($Micro > self::MAX_TIME && !in_array($document, IGNORE_PAGE_MAX_TIME)) { - $Reason[] = number_format($Micro, 3) . ' ms'; - } + public function profile(User $user, bool $profile): ErrorLog|null { + $reason = []; $errorTotal = count($this->errorList()); - if ($errorTotal > self::MAX_ERRORS) { - $Reason[] = "$errorTotal PHP errors"; - } - $Ram = memory_get_usage(true); - if ($Ram > self::MAX_MEMORY && !in_array($document, IGNORE_PAGE_MAX_MEMORY)) { - $Reason[] = byte_format($Ram) . ' RAM used'; + if ($errorTotal > 0) { + $reason[] = "$errorTotal PHP errors"; } $this->db->loadPreviousWarning(); // see comment in MYSQL::query - if (isset($_REQUEST['profile'])) { - $Reason[] = 'Requested by ' . $user->username(); + if ($profile) { + $reason[] = "Requested by {$user->username()}"; } - if (isset($Reason[0])) { - $this->analysis( + if ($reason !== []) { + return $this->analysis( $user->requestContext()->module(), - implode(', ', $Reason) + implode(', ', $reason) ); - return true; } - - return false; + return null; } public function saveCase( @@ -122,14 +108,14 @@ class Debug { return $errorLog; } - public function analysis(string $module, string $message, string $report = ''): void { + public function analysis(string $module, string $message, string $report = ''): ErrorLog|null { $uri = empty($_SERVER['REQUEST_URI']) ? '' : substr($_SERVER['REQUEST_URI'], 1); if ( - PHP_SAPI === 'cli' + (PHP_SAPI === 'cli' && !str_ends_with($_SERVER["SCRIPT_NAME"], "vendor/bin/phpunit")) || in_array($uri, ['tools.php?action=db_sandbox']) ) { // Don't spam IRC from Boris or these pages - return; + return null; } if (empty($report)) { $report = $message; @@ -139,6 +125,7 @@ class Debug { . SITE_URL . "/tools.php?action=analysis&case={$case->id} " . SITE_URL . "/{$uri}" ); + return $case; } public function saveError(\Error|\Exception $e): ErrorLog { @@ -286,4 +273,103 @@ class Debug { 'Script end' => Time::sqlTime(microtime(true)), ]; } + + /* A list of keys to represent durations (50ms, 100ms, 200ms ... 1000ms and then 1s increments up to 60s) */ + public function durationHistogramKeyList(): array { + return array_map( + fn ($t) => sprintf('exec_d_%05d', $t), + [ + 50, + ...array_map( + fn ($t) => $t * 100, + range(1, 10), + ), + ...array_map( + fn ($t) => $t * 1000, + range(2, 60), + ) + ] + ); + } + + /* A list of keys to represent memory sizes in 1MiB increments */ + public function memoryHistogramKeyList(): array { + return array_map( + fn ($t) => sprintf('exec_m_%03d', $t), + range(1, 128), + ); + } + + /* initialise the duration histogram */ + public function initDurationHistogram(): bool { + return $this->cache->setMulti( + array_fill_keys($this->durationHistogramKeyList(), 0), + 0 + ); + } + + /* initialise the memory histogram */ + public function initMemoryHistogram(): bool { + return $this->cache->setMulti( + array_fill_keys($this->memoryHistogramKeyList(), 0), + 0, + ); + } + + public function durationRound(float $duration): int { + return match (true) { + $duration <= 50000 => 50, + $duration < 1000000 => (int)ceil($duration / 100_000) * 100, + default => (int)ceil($duration / 1_000_000) * 1000, + }; + } + + public function memoryRound(float $size): int { + return (int)($size / (1024 * 1024)); + } + + /* increment the appropriate bucket for the given duration */ + public function storeDuration(float $duration): int { + $rounded = $this->durationRound($duration); + return $this->cache->increment(sprintf('exec_d_%05d', $rounded)) === false + ? 0 + : $rounded; + } + + /* increment the appropriate bucket for the given duration */ + public function storeMemory(float $memory): int { + $rounded = $this->memoryRound($memory); + return $this->cache->increment(sprintf('exec_m_%03d', $rounded)) === false + ? 0 + : $rounded; + } + + /* the duration histogram, an assocative array of msec => count pairs */ + public function durationHistogram(): array { + $histogram = $this->cache->getMulti($this->durationHistogramKeyList()); + if ($histogram === false) { + return []; + } + $result = []; + foreach ($histogram as $key => $value) { + $key = (string)$key; + $duration = (int)substr($key, (int)strrpos($key, '_') + 1); + $result[$duration < 1000 ? "{$duration}ms" : ($duration / 1000) . "s"] = $value; + } + return $result; + } + + /* the duration histogram, an assocative array of msec => count pairs */ + public function memoryHistogram(): array { + $histogram = $this->cache->getMulti($this->memoryHistogramKeyList()); + if ($histogram === false) { + return []; + } + $result = []; + foreach ($histogram as $key => $value) { + $key = (string)$key; + $result[((int)substr($key, (int)strrpos($key, '_') + 1)) . "MiB"] = $value; + } + return $result; + } } diff --git a/app/Error.php b/app/Error.php index 7fe0e9db3..3846d4987 100644 --- a/app/Error.php +++ b/app/Error.php @@ -1,4 +1,5 @@ storeMemory(memory_get_usage(true)); + $Debug->storeDuration($Debug->duration() * 1000000); exit; } diff --git a/app/Util/Twig.php b/app/Util/Twig.php index 80c47bacd..ef1efa97a 100644 --- a/app/Util/Twig.php +++ b/app/Util/Twig.php @@ -216,6 +216,11 @@ class Twig { } )); + $twig->addFilter(new \Twig\TwigFilter( + 'values', + fn ($list) => array_values($list) + )); + $twig->addFunction(new \Twig\TwigFunction('header', fn ($title, $options = []) => new \Twig\Markup( View::header($title, $options), 'UTF-8' diff --git a/gazelle.php b/gazelle.php index d38534d61..64fef3d4d 100644 --- a/gazelle.php +++ b/gazelle.php @@ -103,9 +103,6 @@ if ($Viewer) { header('Location: login.php'); exit; } - if ($Viewer->hasAttr('admin-error-reporting')) { - error_reporting(E_ALL); - } if ($Viewer->permitted('site_disable_ip_history')) { $Viewer->requestContext()->anonymize(); } @@ -177,6 +174,8 @@ try { } finally { $Debug->mark('send to user'); if (!is_null($Viewer)) { - $Debug->profile($Viewer, $module); + $Debug->profile($Viewer, isset($_REQUEST['profile'])); } + $Debug->storeMemory(memory_get_usage(true)); + $Debug->storeDuration($Debug->duration() * 1000000); } diff --git a/lib/bootstrap.php b/lib/bootstrap.php index f3a104a99..5a9b33260 100644 --- a/lib/bootstrap.php +++ b/lib/bootstrap.php @@ -2,14 +2,15 @@ /* require this file to have a fully-initialized Gazelle runtime */ -if (PHP_VERSION_ID < 80403) { - die("Gazelle (Orpheus fork) requires at least PHP version 8.4.3"); +if (PHP_VERSION_ID < 80406) { + die("Gazelle (Orpheus fork) requires at least PHP version 8.4.6"); } foreach (['memcached', 'mysqli'] as $e) { if (!extension_loaded($e)) { die("$e extension not loaded"); } } +error_reporting(E_ALL); date_default_timezone_set('UTC'); if (!defined('SITE_NAME')) { diff --git a/sections/tools/development/process_info.php b/sections/tools/development/process_info.php index a46212656..20894256b 100644 --- a/sections/tools/development/process_info.php +++ b/sections/tools/development/process_info.php @@ -11,6 +11,15 @@ if (!$Viewer->permitted('admin_site_debug')) { Error403::error(); } +if (($_GET['view'] ?? '') === 'histogram') { + global $Debug; + echo $Twig->render('admin/process-histogram.twig', [ + 'duration' => $Debug->durationHistogram(), + 'memory' => $Debug->memoryHistogram(), + ]); + exit; +} + $proc = []; if (preg_match('/.*\/(.*)/', PHP_BINARY, $match, PREG_UNMATCHED_AS_NULL)) { $binary = $match[1]; diff --git a/templates/admin/process-histogram.twig b/templates/admin/process-histogram.twig new file mode 100644 index 000000000..049401019 --- /dev/null +++ b/templates/admin/process-histogram.twig @@ -0,0 +1,83 @@ +{{ header('Process histograms', {'js': 'vendor/highcharts,vendor/highcharts_custom'}) }} +
+
+

Process histograms

+
+
+ PHP processes +
+
+
+
+
+
+
+
+ +{{ footer() }} diff --git a/templates/admin/process-list.twig b/templates/admin/process-list.twig index b3f0b05d0..f2937896d 100644 --- a/templates/admin/process-list.twig +++ b/templates/admin/process-list.twig @@ -1,5 +1,11 @@ {{ header('PHP Processes') }}
+
+

PHP processes

+
+ Performance histograms +
+
@@ -7,7 +13,7 @@ {% for pid, info in proc %} @@ -20,4 +26,5 @@ {% endfor %}
- {{ proc|length }} process{{ proc|length|plural('es') }} as of {{ now }} + {{ proc|length }} process{{ proc|length|plural('es') }} as of {{ 'now'|date("Y-m-d H:i:s") }}
+
{{ footer() }} diff --git a/tests/phpunit/DebugTest.php b/tests/phpunit/DebugTest.php index aa7131733..f4d07610d 100644 --- a/tests/phpunit/DebugTest.php +++ b/tests/phpunit/DebugTest.php @@ -3,6 +3,7 @@ namespace Gazelle; use PHPUnit\Framework\TestCase; +use PHPUnit\Framework\Attributes\DataProvider; use GazelleUnitTest\Helper; class DebugTest extends TestCase { @@ -13,6 +14,71 @@ class DebugTest extends TestCase { $this->assertGreaterThan(0, $Debug->epochStart(), 'debug-epoch-start'); $this->assertGreaterThan(350, count($Debug->includeList()), 'debug-include-list'); $this->assertTrue(Helper::recentDate(date('Y-m-d H:i:s', (int)$Debug->epochStart()), 180), 'debug-recent-start'); + + $this->assertCount(70, $Debug->durationHistogramKeyList(), 'debug-duration-histo-key-list'); + $this->assertTrue($Debug->initDurationHistogram(), 'debug-duration-init'); + $initial = $Debug->durationHistogram(); + $this->assertCount(70, $initial, 'debug-duration-histo-initial'); + $this->assertEquals(60000, $Debug->storeDuration(59999999.0), 'debug-duration-store'); + $after = $Debug->durationHistogram(); + $this->assertEquals($initial['60s'] + 1, $after['60s'], 'debug-duration-inc'); + + $this->assertCount(128, $Debug->memoryHistogramKeyList(), 'debug-memory-histo-key-list'); + $this->assertTrue($Debug->initMemoryHistogram(), 'debug-memory-init'); + $initial = $Debug->memoryHistogram(); + $this->assertCount(128, $initial, 'debug-memory-histo-initial'); + $this->assertEquals(128, $Debug->storeMemory(134217728), 'debug-memory-store'); + $after = $Debug->memoryHistogram(); + $this->assertEquals($initial['128MiB'] + 1, $after['128MiB'], 'debug-memory-inc'); + } + + public static function providerDurationRound(): array { + return [ + ['debug-neg-dur', 50, -1.0], + ['debug-0-dur', 50, 0.0], + ['debug-0.1-dur', 50, 0.1], + ['debug-1-dur', 50, 1.0], + ['debug-10-dur', 50, 10.0], + ['debug-100-dur', 50, 100.0], + ['debug-1000-dur', 50, 1000.0], + ['debug-10000-dur', 50, 10000.0], + ['debug-49999-dur', 50, 49999.99999999], + ['debug-50000-dur', 50, 50000.0], + ['debug-50001-dur', 100, 50000.00000000001], + ['debug-99999-dur', 100, 99999.99999999999], + ['debug-100000-dur', 100, 100000.0], + ['debug-100001-dur', 200, 100000.00000000001], + ['debug-899999-dur', 900, 899999.99999999999], + ['debug-999999-dur', 1000, 999999.99999999999], + ['debug-1000000-dur', 1000, 1000000.00000000000], + ['debug-1000001-dur', 2000, 1000000.0000000001], + ['debug-1999999-dur', 2000, 1999999.9999999999], + ['debug-19999999-dur', 20000, 19999999.9999999999], + ]; + } + + #[DataProvider('providerDurationRound')] + public function testDebugDurationRound(string $name, int $rounded, float $input): void { + global $Debug; + $this->assertEquals($rounded, $Debug->durationRound($input), $name); + } + + public static function providerMemoryRound(): array { + return [ + ['debug-0-mem', 0, 0], + ['debug-1M--mem', 0, 1048575], + ['debug-1M-mem', 1, 1048576], + ['debug-1M+-mem', 1, 1048577], + ['debug-64M--mem', 63, 67108863], + ['debug-64M-mem', 64, 67108864], + ['debug-64M+-mem', 64, 67108865], + ]; + } + + #[DataProvider('providerMemoryRound')] + public function testDebugMemoryRound(string $name, int $rounded, float $input): void { + global $Debug; + $this->assertEquals($rounded, $Debug->memoryRound($input), $name); } public function testCreate(): void { @@ -46,7 +112,7 @@ class DebugTest extends TestCase { $this->assertEquals(1, $case->remove(), 'errorlog-remove'); } - public function testCase(): void { + public function testDebugCase(): void { global $Cache; $key = 'phpunit_' . randomString(); $Cache->cache_value($key, 'phpunit', 60); @@ -84,6 +150,21 @@ class DebugTest extends TestCase { $case->remove(); } + public function testDebugError(): void { + $this->expectException(\DivisionByZeroError::class); + try { + $fail = 1 / 0; /** @phpstan-ignore-line binaryOp.invalid */ + } catch (\DivisionByZeroError $e) { + global $Debug; + $case = $Debug->saveError($e); + $this->assertEquals('cli', $case->uri(), 'debug-error-case-uri'); + $this->assertEquals('Division by zero', $case->trace()[0], 'debug-error-case-trace'); + $case->remove(); + // keep phpunit happy + throw $e; + } + } + public function testMark(): void { global $Debug; $message = 'phpunit-' . randomString(); diff --git a/tests/phpunit/UserTest.php b/tests/phpunit/UserTest.php index 5c9ddbb84..9df7215ed 100644 --- a/tests/phpunit/UserTest.php +++ b/tests/phpunit/UserTest.php @@ -562,4 +562,14 @@ class UserTest extends TestCase { ); $second->remove(); } + + public function testDebugProfile(): void { + global $Debug; + $Debug->flush(); // clear out the accumulated errors + $case = $Debug->profile($this->user, false); + $this->assertNull($case, 'user-debug-profile-no-reason'); + $case = $Debug->profile($this->user, true); + $this->assertInstanceOf(ErrorLog::class, $case, 'user-debug-profile-a-reason'); + $case->remove(); + } }