streamline debug reporting

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

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 {
+    public function profile(User $user, bool $profile): ErrorLog|null {
-        $Reason = [];
+        $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';
-        }
 
         $errorTotal = count($this->errorList());
-        if ($errorTotal > self::MAX_ERRORS) {
+        if ($errorTotal > 0) {
-            $Reason[] = "$errorTotal PHP 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';
         }
 
         $this->db->loadPreviousWarning(); // see comment in MYSQL::query
 
-        if (isset($_REQUEST['profile'])) {
+        if ($profile) {
-            $Reason[] = 'Requested by ' . $user->username();
+            $reason[] = "Requested by {$user->username()}";
         }
 
-        if (isset($Reason[0])) {
+        if ($reason !== []) {
-            $this->analysis(
+            return $this->analysis(
                 $user->requestContext()->module(),
-                implode(', ', $Reason)
+                implode(', ', $reason)
             );
-            return true;
         }
-
+        return null;
-        return false;
     }
 
     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;
+    }
 }

app/Error.php

@@ -1,4 +1,5 @@
 <?php
+/** @phpstan-var \Gazelle\Debug $Debug */
 
 declare(strict_types=1);
 
@@ -7,6 +8,9 @@ namespace Gazelle;
 abstract class Error extends Base {
     public static function error(string $message = ''): never {
         echo static::payload($message);
+        global $Debug;
+        $Debug->storeMemory(memory_get_usage(true));
+        $Debug->storeDuration($Debug->duration() * 1000000);
         exit;
     }
 

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'

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);
 }

lib/bootstrap.php

@@ -2,14 +2,15 @@
 
 /* require this file to have a fully-initialized Gazelle runtime */
 
-if (PHP_VERSION_ID < 80403) {
+if (PHP_VERSION_ID < 80406) {
-    die("Gazelle (Orpheus fork) requires at least PHP version 8.4.3");
+    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')) {

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];

templates/admin/process-histogram.twig

@@ -0,0 +1,83 @@
+{{ header('Process histograms', {'js': 'vendor/highcharts,vendor/highcharts_custom'}) }}
+<div class="thin">
+    <div class="header">
+        <h3>Process histograms</h3>
+    </div>
+    <div class="linkbox">
+        <a href="?action=process_info" class="brackets">PHP processes</a>
+    </div>
+    <div class="box pad center">
+        <figure class="highcharts-figure"><div id="process-duration"></div></figure>
+    </div>
+    <div class="box pad center">
+        <figure class="highcharts-figure"><div id="process-memory"></div></figure>
+    </div>
+</div>
+<script>
+document.addEventListener('DOMContentLoaded', () => {
+    Highcharts.chart('process-duration', {
+        chart: {
+            type: 'column',
+            plotBackgroundColor: '#051401',
+            backgroundColor: '#000000',
+        },
+        title: {
+            text: 'Historical Process Duration',
+            style: { color: '#c0c0c0', },
+        },
+        credits: { enabled: false },
+        xAxis: {
+            categories: {{ duration|keys|json_encode|raw }},
+        },
+        yAxis: [
+            {
+                labels: { format: '{value}', style: { color: Highcharts.getOptions().colors[2] }},
+                title: { text: 'Total', style: { color: Highcharts.getOptions().colors[2] }},
+            }
+        ],
+        tooltip: {
+            headerFormat: '<b>{point.x}</b><br/>',
+            pointFormat: '{series.name}: {point.y}'
+        },
+        plotOptions: {
+            column: { stacking: 'normal' }
+        },
+        series: [
+            { type: 'column', name: 'Total',  data: {{ duration|values|json_encode|raw }} },
+        ]
+    });
+    Highcharts.chart('process-memory', {
+        chart: {
+            type: 'column',
+            plotBackgroundColor: '#051401',
+            backgroundColor: '#000000',
+        },
+        title: {
+            text: 'Historical Memory Duration',
+            style: { color: '#c0c0c0', },
+        },
+        credits: { enabled: false },
+        xAxis: {
+            categories: {{ memory|keys|json_encode|raw }},
+        },
+        yAxis: [
+            {
+                labels: { format: '{value}', style: { color: Highcharts.getOptions().colors[2] }},
+                title: { text: 'Total', style: { color: Highcharts.getOptions().colors[2] }},
+            }
+        ],
+        tooltip: {
+            headerFormat: '<b>{point.x}</b><br/>',
+            pointFormat: '{series.name}: {point.y}'
+        },
+        plotOptions: {
+            column: { stacking: 'normal' }
+        },
+        series: [
+            { type: 'column', name: 'Total',  data: {{ memory|values|json_encode|raw }} },
+        ]
+    })
+});
+
+</script>
+{{ footer() }}

templates/admin/process-list.twig

@@ -1,5 +1,11 @@
 {{ header('PHP Processes') }}
 <div class="thin">
+    <div class="header">
+        <h3>PHP processes</h3>
+        <div class="linkbox">
+            <a href="?action=process_info&amp;view=histogram" class="brackets">Performance histograms</a>
+        </div>
+    </div>
     <table class="process_info">
         <colgroup>
             <col class="process_info_pid" />
@@ -7,7 +13,7 @@
         </colgroup>
         <tr class="colhead_dark">
             <td colspan="2">
-                {{ 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") }}
             </td>
         </tr>
 {% for pid, info in proc %}
@@ -20,4 +26,5 @@
 {% endfor %}
     </table>
 </div>
+<br />
 {{ footer() }}

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();

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();
+    }
 }