diff --git a/app/Support/Http/HttpPerformanceLogAnalyzer.php b/app/Support/Http/HttpPerformanceLogAnalyzer.php index 83c63cda..4bbdd810 100644 --- a/app/Support/Http/HttpPerformanceLogAnalyzer.php +++ b/app/Support/Http/HttpPerformanceLogAnalyzer.php @@ -10,16 +10,23 @@ namespace App\Support\Http; * Multi-value upstream timings (retries): use the **sum** of numeric parts * as the upstream total for that request. "-" and empty → null. * Percentiles use nearest-rank (ceil(p * n), 1-indexed). + * + * Exact --status=404 means HTTP 404 only (not 4xx). Classes are 4xx/5xx. */ final class HttpPerformanceLogAnalyzer { + /** Ignore gaps shorter than this when judging 24h source coverage. */ + public const COVERAGE_TOLERANCE_SECONDS = 900; + public function __construct(private readonly HttpUriNormalizer $uris) { } /** + * @param string|list $input * @param array{ * since?: ?string, + * until?: ?string, * min_requests?: int, * top?: int, * status?: ?string, @@ -30,139 +37,178 @@ final class HttpPerformanceLogAnalyzer * } $options * @return array */ - public function analyze(string $file, array $options = []): array + public function analyze(string|array $input, array $options = []): array { - $since = $this->sinceCutoff($options['since'] ?? null, $options['now'] ?? new \DateTimeImmutable('now')); + $files = $this->normalizeInputList($input); + $now = $options['now'] ?? new \DateTimeImmutable('now'); + $requestedStart = $this->sinceCutoff($options['since'] ?? null, $now); + $requestedEnd = $this->untilInstant($options['until'] ?? null, $now); $minRequests = max(1, (int) ($options['min_requests'] ?? 1)); $top = max(1, (int) ($options['top'] ?? 20)); - $statusFilter = isset($options['status']) ? strtolower((string) $options['status']) : null; + $statusFilter = $this->parseStatusFilter($options['status'] ?? null); $uriFilter = $options['uri'] ?? null; $hostFilter = isset($options['host']) ? (string) $options['host'] : ''; - $slowMs = isset($options['slow_ms']) ? (float) $options['slow_ms'] / 1000 : null; + $slowMs = isset($options['slow_ms']) && $options['slow_ms'] !== null + ? (float) $options['slow_ms'] / 1000 + : null; $skipped = 0; + $linesScanned = 0; + $parseable = 0; $families = []; $slowest = []; $statusCounts = ['4xx' => 0, '5xx' => 0, '499' => 0, 'total' => 0]; + $sources = []; + $earliestParseable = null; + $latestParseable = null; + $earliestMatching = null; + $latestMatching = null; - $handle = fopen($file, 'r'); - if ($handle === false) { - throw new \RuntimeException('Unable to open performance log: '.$file); - } + foreach ($files as $file) { + $source = [ + 'path' => $file, + 'gzip' => str_ends_with(strtolower($file), '.gz'), + 'lines_scanned' => 0, + 'parseable' => 0, + 'in_window' => 0, + 'error' => null, + ]; - try { - while (($line = fgets($handle)) !== false) { - $line = trim($line); - if ($line === '') { - continue; - } - - $row = json_decode($line, true); - if (! is_array($row)) { - $skipped++; - continue; - } - - $time = $this->parseTime((string) ($row['time'] ?? '')); - if ($since !== null && ($time === null || $time < $since)) { - continue; - } - - $requestTime = $this->parseFloat($row['request_time'] ?? null); - if ($requestTime === null) { - $skipped++; - continue; - } - - $status = (int) ($row['status'] ?? 0); - if ($statusFilter === '5xx' && ($status < 500 || $status > 599)) { - continue; - } - if ($statusFilter === '4xx' && ($status < 400 || $status > 499)) { - continue; - } - if ($statusFilter === '499' && $status !== 499) { - continue; - } - - $host = (string) ($row['host'] ?? ''); - if ($hostFilter !== '' && $host !== $hostFilter) { - continue; - } - - $uri = $this->uris->normalize((string) ($row['uri'] ?? '/')); - if (is_string($uriFilter) && $uriFilter !== '' && ! str_starts_with($uri, $uriFilter)) { - continue; - } - - if ($slowMs !== null && $requestTime < $slowMs) { - continue; - } - - $upstreamResponse = $this->parseUpstream($row['upstream_response_time'] ?? null); - $upstreamHeader = $this->parseUpstream($row['upstream_header_time'] ?? null); - $bytes = (int) ($row['bytes'] ?? 0); - $method = (string) ($row['method'] ?? ''); - - $statusCounts['total']++; - if ($status === 499) { - $statusCounts['499']++; - } elseif ($status >= 500) { - $statusCounts['5xx']++; - } elseif ($status >= 400) { - $statusCounts['4xx']++; - } - - $familyKey = $host."\n".$uri; - $families[$familyKey] ??= [ - 'host' => $host, - 'uri' => $uri, - 'count' => 0, - 'times' => [], - 'upstream_sum' => 0.0, - 'upstream_n' => 0, - 'header_sum' => 0.0, - 'header_n' => 0, - 'bytes_sum' => 0, - '4xx' => 0, - '5xx' => 0, - '499' => 0, - '404' => 0, - ]; - $families[$familyKey]['count']++; - $families[$familyKey]['times'][] = $requestTime; - $families[$familyKey]['bytes_sum'] += $bytes; - if ($upstreamResponse !== null) { - $families[$familyKey]['upstream_sum'] += $upstreamResponse; - $families[$familyKey]['upstream_n']++; - } - if ($upstreamHeader !== null) { - $families[$familyKey]['header_sum'] += $upstreamHeader; - $families[$familyKey]['header_n']++; - } - if ($status === 499) { - $families[$familyKey]['499']++; - } elseif ($status >= 500) { - $families[$familyKey]['5xx']++; - } elseif ($status >= 400) { - $families[$familyKey]['4xx']++; - if ($status === 404) { - $families[$familyKey]['404']++; - } - } - - $slowest[] = [ - 'time' => $row['time'] ?? null, - 'host' => $host, - 'uri' => $uri, - 'method' => $method, - 'status' => $status, - 'request_time' => $requestTime, - 'upstream_response_time' => $upstreamResponse, - ]; + $handle = $this->openStream($file); + if ($handle === false) { + $source['error'] = 'unreadable'; + $sources[] = $source; + continue; } - } finally { - fclose($handle); + + try { + while (($line = fgets($handle)) !== false) { + $linesScanned++; + $source['lines_scanned']++; + $line = trim($line); + if ($line === '') { + continue; + } + + $row = json_decode($line, true); + if (! is_array($row)) { + $skipped++; + continue; + } + + $time = $this->parseTime((string) ($row['time'] ?? '')); + $requestTime = $this->parseFloat($row['request_time'] ?? null); + if ($requestTime === null) { + $skipped++; + continue; + } + + $parseable++; + $source['parseable']++; + if ($time instanceof \DateTimeImmutable) { + $earliestParseable = $this->minTime($earliestParseable, $time); + $latestParseable = $this->maxTime($latestParseable, $time); + } + + if ($requestedStart !== null && ($time === null || $time < $requestedStart)) { + continue; + } + if ($requestedEnd !== null && ($time === null || $time > $requestedEnd)) { + continue; + } + + $status = (int) ($row['status'] ?? 0); + if (! $this->statusMatches($status, $statusFilter)) { + continue; + } + + $host = (string) ($row['host'] ?? ''); + if ($hostFilter !== '' && $host !== $hostFilter) { + continue; + } + + $uri = $this->uris->normalize((string) ($row['uri'] ?? '/')); + if (is_string($uriFilter) && $uriFilter !== '' && ! str_starts_with($uri, $uriFilter)) { + continue; + } + + if ($slowMs !== null && $requestTime < $slowMs) { + continue; + } + + $source['in_window']++; + if ($time instanceof \DateTimeImmutable) { + $earliestMatching = $this->minTime($earliestMatching, $time); + $latestMatching = $this->maxTime($latestMatching, $time); + } + + $upstreamResponse = $this->parseUpstream($row['upstream_response_time'] ?? null); + $upstreamHeader = $this->parseUpstream($row['upstream_header_time'] ?? null); + $bytes = (int) ($row['bytes'] ?? 0); + $method = (string) ($row['method'] ?? ''); + + $statusCounts['total']++; + if ($status === 499) { + $statusCounts['499']++; + } elseif ($status >= 500) { + $statusCounts['5xx']++; + } elseif ($status >= 400) { + $statusCounts['4xx']++; + } + + $familyKey = $host."\n".$uri; + $families[$familyKey] ??= [ + 'host' => $host, + 'uri' => $uri, + 'count' => 0, + 'times' => [], + 'upstream_sum' => 0.0, + 'upstream_n' => 0, + 'header_sum' => 0.0, + 'header_n' => 0, + 'bytes_sum' => 0, + '4xx' => 0, + '5xx' => 0, + '499' => 0, + '404' => 0, + ]; + $families[$familyKey]['count']++; + $families[$familyKey]['times'][] = $requestTime; + $families[$familyKey]['bytes_sum'] += $bytes; + if ($upstreamResponse !== null) { + $families[$familyKey]['upstream_sum'] += $upstreamResponse; + $families[$familyKey]['upstream_n']++; + } + if ($upstreamHeader !== null) { + $families[$familyKey]['header_sum'] += $upstreamHeader; + $families[$familyKey]['header_n']++; + } + if ($status === 499) { + $families[$familyKey]['499']++; + } elseif ($status >= 500) { + $families[$familyKey]['5xx']++; + } elseif ($status >= 400) { + $families[$familyKey]['4xx']++; + if ($status === 404) { + $families[$familyKey]['404']++; + } + } + + $slowest[] = [ + 'time' => $row['time'] ?? null, + 'host' => $host, + 'uri' => $uri, + 'method' => $method, + 'status' => $status, + 'request_time' => $requestTime, + ]; + $slowest[array_key_last($slowest)]['upstream_response_time'] = $upstreamResponse; + } + } finally { + fclose($handle); + } + + $sources[] = $source; } usort($slowest, static fn (array $a, array $b): int => $b['request_time'] <=> $a['request_time']); @@ -213,8 +259,24 @@ final class HttpPerformanceLogAnalyzer $by404 = array_values(array_filter($summaries, static fn (array $row): bool => ($row['404'] ?? 0) > 0)); usort($by404, static fn (array $a, array $b): int => $b['404'] <=> $a['404']); + $coverage = $this->coverageReport( + $requestedStart, + $requestedEnd, + $earliestParseable, + $latestParseable, + $earliestMatching, + $latestMatching, + ); + return [ 'skipped' => $skipped, + 'lines_scanned' => $linesScanned, + 'parseable' => $parseable, + 'source_files' => count($files), + 'sources' => $sources, + 'coverage' => $coverage, + 'warnings' => $coverage['warnings'], + 'sample_empty' => $statusCounts['total'] === 0, 'totals' => $statusCounts, 'by_p95' => array_slice($byP95, 0, $top), 'by_p99' => array_slice($byP99, 0, $top), @@ -229,6 +291,48 @@ final class HttpPerformanceLogAnalyzer ]; } + /** + * @param list $paths + * @return list + */ + public function deduplicatePaths(array $paths): array + { + $seen = []; + $out = []; + foreach ($paths as $path) { + $path = str_replace('\\', '/', (string) $path); + if ($path === '') { + continue; + } + $resolved = realpath($path) ?: $path; + $key = strtolower($resolved); + if (isset($seen[$key])) { + continue; + } + $seen[$key] = true; + $out[] = $path; + } + + return array_values($out); + } + + /** + * @return list + */ + public function expandGlob(string $pattern): array + { + $matches = glob($pattern, GLOB_NOSORT) ?: []; + $files = []; + foreach ($matches as $match) { + if (is_file($match)) { + $files[] = $match; + } + } + natsort($files); + + return array_values($files); + } + /** * Nearest-rank: rank = ceil(p * n), 1-indexed. * @@ -274,6 +378,135 @@ final class HttpPerformanceLogAnalyzer return $found ? $sum : null; } + /** + * @param string|list $input + * @return list + */ + private function normalizeInputList(string|array $input): array + { + $files = is_array($input) ? $input : [$input]; + $files = $this->deduplicatePaths(array_map('strval', $files)); + if ($files === []) { + throw new \InvalidArgumentException('No performance log files were provided.'); + } + + return $files; + } + + /** + * @return resource|false + */ + private function openStream(string $file) + { + if (str_ends_with(strtolower($file), '.gz')) { + return @gzopen($file, 'rb'); + } + + return @fopen($file, 'r'); + } + + /** + * @return array{type: string, code?: int, class?: string} + */ + public function parseStatusFilter(?string $raw): array + { + if ($raw === null || $raw === '') { + return ['type' => 'none']; + } + + $value = strtolower(trim($raw)); + if ($value === '4xx') { + return ['type' => 'class', 'class' => '4xx']; + } + if ($value === '5xx') { + return ['type' => 'class', 'class' => '5xx']; + } + if (preg_match('/^[1-5][0-9]{2}$/', $value) === 1) { + return ['type' => 'exact', 'code' => (int) $value]; + } + + throw new \InvalidArgumentException('Invalid --status value: '.$raw); + } + + /** + * @param array{type: string, code?: int, class?: string} $filter + */ + private function statusMatches(int $status, array $filter): bool + { + return match ($filter['type']) { + 'none' => true, + 'exact' => $status === (int) ($filter['code'] ?? 0), + 'class' => ($filter['class'] ?? '') === '5xx' + ? ($status >= 500 && $status <= 599) + : ($status >= 400 && $status <= 499), + default => true, + }; + } + + /** + * @return array + */ + private function coverageReport( + ?\DateTimeImmutable $requestedStart, + ?\DateTimeImmutable $requestedEnd, + ?\DateTimeImmutable $earliestParseable, + ?\DateTimeImmutable $latestParseable, + ?\DateTimeImmutable $earliestMatching, + ?\DateTimeImmutable $latestMatching, + ): array { + $warnings = []; + $complete = true; + if ($requestedStart instanceof \DateTimeImmutable && $requestedEnd instanceof \DateTimeImmutable) { + if (! $earliestParseable instanceof \DateTimeImmutable || ! $latestParseable instanceof \DateTimeImmutable) { + $complete = false; + $warnings[] = 'Observed records do not demonstrate full requested coverage.'; + } else { + $startGap = $earliestParseable->getTimestamp() - $requestedStart->getTimestamp(); + $endGap = $requestedEnd->getTimestamp() - $latestParseable->getTimestamp(); + if ($startGap > self::COVERAGE_TOLERANCE_SECONDS || $endGap > self::COVERAGE_TOLERANCE_SECONDS) { + $complete = false; + $warnings[] = sprintf( + 'WARNING: Requested window is not fully covered by supplied logs. Requested: %s → %s Observed: %s → %s', + $requestedStart->format(\DateTimeInterface::ATOM), + $requestedEnd->format(\DateTimeInterface::ATOM), + $earliestParseable->format(\DateTimeInterface::ATOM), + $latestParseable->format(\DateTimeInterface::ATOM), + ); + } + } + } + + return [ + 'requested_start' => $requestedStart?->format(\DateTimeInterface::ATOM), + 'requested_end' => $requestedEnd?->format(\DateTimeInterface::ATOM), + 'observed_earliest_parseable' => $earliestParseable?->format(\DateTimeInterface::ATOM), + 'observed_latest_parseable' => $latestParseable?->format(\DateTimeInterface::ATOM), + 'observed_earliest_matching' => $earliestMatching?->format(\DateTimeInterface::ATOM), + 'observed_latest_matching' => $latestMatching?->format(\DateTimeInterface::ATOM), + 'tolerance_seconds' => self::COVERAGE_TOLERANCE_SECONDS, + 'complete' => $complete, + 'warnings' => $warnings, + ]; + } + + private function minTime(?\DateTimeImmutable $current, \DateTimeImmutable $candidate): \DateTimeImmutable + { + if ($current === null || $candidate < $current) { + return $candidate; + } + + return $current; + } + + private function maxTime(?\DateTimeImmutable $current, \DateTimeImmutable $candidate): \DateTimeImmutable + { + if ($current === null || $candidate > $current) { + return $candidate; + } + + return $current; + } + private function parseFloat(mixed $value): ?float { if ($value === null || $value === '' || $value === '-') { @@ -306,7 +539,7 @@ final class HttpPerformanceLogAnalyzer } if (preg_match('/^(\d+)(h|d|m)$/', strtolower($since), $matches) !== 1) { - return null; + return $this->parseTime($since); } $n = (int) $matches[1]; @@ -319,4 +552,13 @@ final class HttpPerformanceLogAnalyzer return $now->sub($interval); } + + private function untilInstant(?string $until, \DateTimeImmutable $now): \DateTimeImmutable + { + if ($until === null || $until === '') { + return $now; + } + + return $this->parseTime($until) ?? $now; + } } diff --git a/docs/optimization-m12.6-http-performance-analyzer.md b/docs/optimization-m12.6-http-performance-analyzer.md new file mode 100644 index 00000000..89665055 --- /dev/null +++ b/docs/optimization-m12.6-http-performance-analyzer.md @@ -0,0 +1,49 @@ +# M12.6 — Performance Analyzer Correctness + Rotation-Safe 24h Reporting + +Analyzer-only. No nginx, FPM, Redis, or request-path changes. + +## Status filters + +| Value | Meaning | +| --- | --- | +| `--status=404` | **exact** HTTP 404 only | +| `--status=500` | exact 500 | +| `--status=4xx` | 400–499 (includes 404, 422, 499) | +| `--status=5xx` | 500–599 | + +`--status=404` is **not** a 4xx class. Malformed values (`foo`, `40`, `9999`) exit 2. + +**Bug:** the old analyzer only special-cased `4xx` / `5xx` / `499`. `--status=404` was ignored, so almost every row was returned. + +## Inputs + +- `--file=path` (repeatable) +- `--glob='…/skinbase-performance.log*'` +- default single file remains `/var/log/nginx/skinbase-performance.log` +- `.gz` streamed with `gzopen` (no `zcat`, no full-file decompress) +- duplicate **paths** are collapsed via `realpath`; duplicate **events** are kept + +## Time / coverage + +- `--since=24h` (or `30m` / `7d`) from `--until` or now +- optional `--until=` ISO-8601, `--hours=24` alias for `--since=24h` +- Coverage uses parseable timestamps in the supplied files (15-minute tolerance) +- Incomplete sources emit: `Observed records do not demonstrate full requested coverage.` + +## Backward compatible + +```bash +php scripts/analyze-http-performance.php --file=/var/log/nginx/skinbase-performance.log --since=24h --host=skinbase.org +``` + +## Rotation-aware 24h + +```bash +sudo php /opt/www/virtual/SkinbaseNova/scripts/analyze-http-performance.php \ + --glob='/var/log/nginx/skinbase-performance.log*' \ + --since=24h \ + --host=skinbase.org \ + --top=20 +``` + +`skinbase` may not be able to read `/var/log/nginx`; use the same sudo model as today. The analyzer is read-only. diff --git a/scripts/analyze-http-performance.php b/scripts/analyze-http-performance.php index 7a839f0f..0b914a5c 100644 --- a/scripts/analyze-http-performance.php +++ b/scripts/analyze-http-performance.php @@ -3,10 +3,18 @@ declare(strict_types=1); /** - * Read-only analyzer for /var/log/nginx/skinbase-performance.log + * Read-only analyzer for nginx skinbase-performance JSON logs. * - * Usage: - * php scripts/analyze-http-performance.php --file=/var/log/nginx/skinbase-performance.log --since=24h --top=20 --host=skinbase.org + * Single file (backward compatible): + * php scripts/analyze-http-performance.php --file=/var/log/nginx/skinbase-performance.log --since=24h --host=skinbase.org + * + * Rotation-aware 24h: + * php scripts/analyze-http-performance.php --glob='/var/log/nginx/skinbase-performance.log*' --since=24h --host=skinbase.org + * + * Status: + * --status=404 exact HTTP 404 + * --status=4xx 400-499 + * --status=5xx 500-599 */ use App\Support\Http\HttpPerformanceLogAnalyzer; @@ -14,9 +22,11 @@ use App\Support\Http\HttpUriNormalizer; require __DIR__.'/../vendor/autoload.php'; +$files = []; +$globs = []; $options = [ - 'file' => '/var/log/nginx/skinbase-performance.log', 'since' => '24h', + 'until' => null, 'min_requests' => 1, 'top' => 20, 'status' => null, @@ -31,9 +41,18 @@ foreach (array_slice($argv, 1) as $arg) { exit(2); } [$key, $value] = array_pad(explode('=', substr($arg, 2), 2), 2, '1'); + if ($key === 'file') { + $files[] = $value; + continue; + } + if ($key === 'glob') { + $globs[] = $value; + continue; + } $map = [ - 'file' => 'file', 'since' => 'since', + 'until' => 'until', + 'hours' => 'hours', 'min-requests' => 'min_requests', 'top' => 'top', 'status' => 'status', @@ -48,21 +67,52 @@ foreach (array_slice($argv, 1) as $arg) { $options[$map[$key]] = $value; } -$file = (string) $options['file']; -if (! is_readable($file)) { - fwrite(STDERR, "Cannot read {$file}\n"); - exit(1); +if (isset($options['hours']) && is_numeric($options['hours'])) { + $options['since'] = ((int) $options['hours']).'h'; } $analyzer = new HttpPerformanceLogAnalyzer(new HttpUriNormalizer()); -$result = $analyzer->analyze($file, [ - 'since' => $options['since'], - 'min_requests' => (int) $options['min_requests'], - 'top' => (int) $options['top'], - 'status' => $options['status'], - 'uri' => $options['uri'], - 'host' => $options['host'], - 'slow_ms' => $options['slow_ms'] !== null ? (float) $options['slow_ms'] : null, -]); + +$discovered = $files; +foreach ($globs as $pattern) { + $discovered = array_merge($discovered, $analyzer->expandGlob($pattern)); +} + +if ($discovered === [] && $globs === []) { + $discovered[] = '/var/log/nginx/skinbase-performance.log'; +} + +$discovered = $analyzer->deduplicatePaths($discovered); +if ($discovered === []) { + fwrite(STDERR, "No matching performance log files.\n"); + exit(1); +} + +foreach ($discovered as $path) { + if (! is_readable($path)) { + fwrite(STDERR, "Cannot read {$path}\n"); + exit(1); + } +} + +try { + $result = $analyzer->analyze($discovered, [ + 'since' => $options['since'], + 'until' => $options['until'], + 'min_requests' => (int) $options['min_requests'], + 'top' => (int) $options['top'], + 'status' => $options['status'], + 'uri' => $options['uri'], + 'host' => $options['host'], + 'slow_ms' => $options['slow_ms'] !== null ? (float) $options['slow_ms'] : null, + ]); +} catch (InvalidArgumentException $e) { + fwrite(STDERR, $e->getMessage()."\n"); + exit(2); +} + +foreach ($result['warnings'] ?? [] as $warning) { + fwrite(STDERR, $warning."\n"); +} echo json_encode($result, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES), PHP_EOL; diff --git a/tests/Unit/Http/HttpPerformanceAnalyzerM126Test.php b/tests/Unit/Http/HttpPerformanceAnalyzerM126Test.php new file mode 100644 index 00000000..84c9ceed --- /dev/null +++ b/tests/Unit/Http/HttpPerformanceAnalyzerM126Test.php @@ -0,0 +1,223 @@ +analyze(rotationFiles(), $extra + [ + 'since' => '24h', + 'now' => analyzerNow(), + 'top' => 50, + 'min_requests' => 1, + ]); +} + +it('filters exact status 404 and does not leak other codes', function () { + $result = analyzeRotation(['status' => '404', 'host' => 'skinbase.org']); + $statuses = collect($result['slowest'])->pluck('status')->unique()->values()->all(); + + expect($result['totals']['total'])->toBe(2) + ->and($statuses)->toBe([404]) + ->and($result['totals']['5xx'])->toBe(0) + ->and($result['totals']['499'])->toBe(0); +}); + +it('filters exact 422 and 500 separately', function () { + $s422 = analyzeRotation(['status' => '422', 'host' => 'skinbase.org']); + $s500 = analyzeRotation(['status' => '500', 'host' => 'skinbase.org']); + + expect($s422['totals']['total'])->toBe(1) + ->and(collect($s422['slowest'])->pluck('status')->all())->toBe([422]) + ->and($s500['totals']['total'])->toBe(1) + ->and(collect($s500['slowest'])->pluck('status')->all())->toBe([500]); +}); + +it('supports 4xx and 5xx classes without treating 404 as a class', function () { + $four = analyzeRotation(['status' => '4xx', 'host' => 'skinbase.org']); + $five = analyzeRotation(['status' => '5xx', 'host' => 'skinbase.org']); + + $fourStatuses = collect($four['slowest'])->pluck('status')->sort()->values()->all(); + $fiveStatuses = collect($five['slowest'])->pluck('status')->sort()->values()->all(); + + expect($fourStatuses)->toBe([404, 404, 422, 499]) + ->and($fiveStatuses)->toBe([500, 502]); +}); + +it('rejects malformed status filters', function () { + $analyzer = new HttpPerformanceLogAnalyzer(new HttpUriNormalizer()); + expect(fn () => $analyzer->parseStatusFilter('foo'))->toThrow(InvalidArgumentException::class) + ->and(fn () => $analyzer->parseStatusFilter('40'))->toThrow(InvalidArgumentException::class) + ->and(fn () => $analyzer->parseStatusFilter('9999'))->toThrow(InvalidArgumentException::class); +}); + +it('includes active, rotated, and gzip files in one window', function () { + $result = analyzeRotation(['host' => 'skinbase.org']); + $paths = collect($result['sources'])->pluck('path')->implode(' '); + + expect($result['source_files'])->toBe(3) + ->and($paths)->toContain('active.log') + ->and($paths)->toContain('rotated.1') + ->and($paths)->toContain('.gz') + ->and($result['totals']['total'])->toBeGreaterThan(5); + + $gz = collect($result['sources'])->first(fn (array $row): bool => str_ends_with($row['path'], '.gz')); + expect($gz['in_window'])->toBeGreaterThan(0); +}); + +it('deduplicates the same file passed twice without dropping distinct events', function () { + $analyzer = new HttpPerformanceLogAnalyzer(new HttpUriNormalizer()); + $active = rotationDir().'/active.log'; + $once = $analyzer->analyze($active, [ + 'since' => '24h', + 'now' => analyzerNow(), + 'host' => 'skinbase.org', + 'min_requests' => 1, + 'top' => 20, + ]); + $twice = $analyzer->analyze([$active, $active], [ + 'since' => '24h', + 'now' => analyzerNow(), + 'host' => 'skinbase.org', + 'min_requests' => 1, + 'top' => 20, + ]); + + expect($twice['source_files'])->toBe(1) + ->and($twice['totals']['total'])->toBe($once['totals']['total']); +}); + +it('does not event-deduplicate identical-looking rows from different files', function () { + $dir = sys_get_temp_dir().'/m126-dup-'.uniqid(); + mkdir($dir); + $line = '{"time":"2026-08-25T07:00:00+02:00","host":"skinbase.org","method":"GET","uri":"/","status":200,"request_time":0.1,"upstream_response_time":"0.1","upstream_connect_time":"0.0","upstream_header_time":"0.1","bytes":1,"request_length":1,"content_type":"text/html","cache":""}'."\n"; + file_put_contents($dir.'/a.log', $line); + file_put_contents($dir.'/b.log', $line); + + $result = (new HttpPerformanceLogAnalyzer(new HttpUriNormalizer()))->analyze( + [$dir.'/a.log', $dir.'/b.log'], + ['since' => '24h', 'now' => analyzerNow(), 'host' => 'skinbase.org', 'min_requests' => 1, 'top' => 10], + ); + + expect($result['totals']['total'])->toBe(2); +}); + +it('applies the time window across rotation and gzip files', function () { + $result = analyzeRotation(['host' => 'skinbase.org']); + $times = collect($result['slowest'])->pluck('time'); + + expect($times->contains('2026-08-24T07:50:00+02:00'))->toBeFalse() + ->and($times->contains('2026-08-25T08:10:00+02:00'))->toBeFalse() + ->and($times->contains('2026-08-24T08:10:00+02:00'))->toBeTrue() + ->and($times->contains('2026-08-24T23:50:00+02:00'))->toBeTrue() + ->and($times->contains('2026-08-25T07:50:00+02:00'))->toBeTrue(); +}); + +it('keeps p50/p95/p99 identical when the same events are split across files', function () { + $analyzer = new HttpPerformanceLogAnalyzer(new HttpUriNormalizer()); + $opts = ['since' => '24h', 'now' => analyzerNow(), 'host' => 'skinbase.org', 'min_requests' => 1, 'top' => 20]; + $files = rotationFiles(); + $combined = sys_get_temp_dir().'/m126-combined-'.uniqid().'.log'; + $blob = ''; + foreach ($files as $file) { + if (str_ends_with($file, '.gz')) { + $blob .= gzdecode(file_get_contents($file)); + } else { + $blob .= file_get_contents($file); + } + if (! str_ends_with($blob, "\n")) { + $blob .= "\n"; + } + } + file_put_contents($combined, $blob); + + $split = $analyzer->analyze($files, $opts); + $single = $analyzer->analyze($combined, $opts); + $splitHome = collect($split['by_count'])->firstWhere('uri', '/'); + $singleHome = collect($single['by_count'])->firstWhere('uri', '/'); + + expect($split['totals']['total'])->toBe($single['totals']['total']) + ->and($splitHome['count'])->toBe($singleHome['count']) + ->and($splitHome['p50'])->toBe($singleHome['p50']) + ->and($splitHome['p95'])->toBe($singleHome['p95']) + ->and($splitHome['p99'])->toBe($singleHome['p99']) + ->and($splitHome['avg'])->toBe($singleHome['avg']) + ->and($splitHome['max'])->toBe($singleHome['max']); +}); + +it('warns when observed records start many hours after the requested window', function () { + $analyzer = new HttpPerformanceLogAnalyzer(new HttpUriNormalizer()); + $result = $analyzer->analyze(rotationDir().'/active.log', [ + 'since' => '24h', + 'now' => analyzerNow(), + 'host' => 'skinbase.org', + 'min_requests' => 1, + 'top' => 10, + ]); + + expect($result['coverage']['complete'])->toBeFalse() + ->and($result['warnings'])->not->toBeEmpty(); +}); + +it('does not warn when parseable records span the requested 24h window', function () { + $result = analyzeRotation(); + + expect($result['coverage']['complete'])->toBeTrue() + ->and($result['warnings'])->toBeEmpty() + ->and($result['coverage']['requested_start'])->toBe('2026-08-24T08:00:00+02:00') + ->and($result['coverage']['requested_end'])->toBe('2026-08-25T08:00:00+02:00'); +}); + +it('reports an empty sample when the host matches nothing', function () { + $result = analyzeRotation(['host' => 'no-such.example']); + + expect($result['sample_empty'])->toBeTrue() + ->and($result['totals']['total'])->toBe(0) + ->and($result['by_count'])->toBe([]); +}); + +it('keeps exact host filtering on mixed rotation files', function () { + $result = analyzeRotation(['host' => 'skinbase.org']); + $hosts = array_unique(array_column($result['by_count'], 'host')); + + expect($hosts)->toBe(['skinbase.org']); +}); diff --git a/tests/fixtures/http-performance/hosts.log b/tests/fixtures/http-performance/hosts.log new file mode 100644 index 00000000..cb01420f --- /dev/null +++ b/tests/fixtures/http-performance/hosts.log @@ -0,0 +1,12 @@ +{"time":"2026-08-24T15:20:00+02:00","host":"skinbase.org","method":"GET","uri":"/art/53867/light-mark-docks","status":200,"request_time":0.400,"upstream_response_time":"0.380","upstream_connect_time":"0.000","upstream_header_time":"0.200","bytes":10000,"request_length":100,"content_type":"text/html","cache":""} +{"time":"2026-08-24T15:21:00+02:00","host":"www.skinbase.org","method":"GET","uri":"/art/53867/light-mark-docks","status":200,"request_time":0.900,"upstream_response_time":"0.880","upstream_connect_time":"0.000","upstream_header_time":"0.200","bytes":10000,"request_length":100,"content_type":"text/html","cache":""} +{"time":"2026-08-24T15:22:00+02:00","host":"thumb.skinbase.org","method":"GET","uri":"/art/1/x","status":200,"request_time":0.050,"upstream_response_time":"-","upstream_connect_time":"-","upstream_header_time":"-","bytes":500,"request_length":80,"content_type":"image/webp","cache":""} +{"time":"2026-08-24T15:23:00+02:00","host":"hub.skinbase.org","method":"GET","uri":"/art/2/y","status":200,"request_time":0.060,"upstream_response_time":"0.040","upstream_connect_time":"0.000","upstream_header_time":"0.030","bytes":800,"request_length":80,"content_type":"text/html","cache":""} +{"time":"2026-08-24T15:24:00+02:00","host":"skinbase.org","method":"GET","uri":"/art/3858/similar","status":200,"request_time":0.220,"upstream_response_time":"0.200","upstream_connect_time":"0.000","upstream_header_time":"0.180","bytes":8000,"request_length":90,"content_type":"text/html","cache":""} +{"time":"2026-08-24T15:25:00+02:00","host":"skinbase.org","method":"GET","uri":"/download/artwork/42026","status":200,"request_time":0.150,"upstream_response_time":"0.140","upstream_connect_time":"0.000","upstream_header_time":"0.100","bytes":200,"request_length":90,"content_type":"application/octet-stream","cache":""} +{"time":"2026-08-24T15:26:00+02:00","host":"skinbase.org","method":"GET","uri":"/api/art/69876/view","status":204,"request_time":0.030,"upstream_response_time":"0.020","upstream_connect_time":"0.000","upstream_header_time":"0.015","bytes":0,"request_length":70,"content_type":"","cache":""} +{"time":"2026-08-24T15:27:00+02:00","host":"skinbase.org","method":"GET","uri":"/api/rank/category/583","status":200,"request_time":0.080,"upstream_response_time":"0.070","upstream_connect_time":"0.000","upstream_header_time":"0.060","bytes":400,"request_length":80,"content_type":"application/json","cache":""} +{"time":"2026-08-24T15:28:00+02:00","host":"skinbase.org","method":"GET","uri":"/academy/prompts/123","status":200,"request_time":0.500,"upstream_response_time":"0.480","upstream_connect_time":"0.000","upstream_header_time":"0.200","bytes":12000,"request_length":90,"content_type":"text/html","cache":""} +{"time":"2026-08-24T15:29:00+02:00","host":"skinbase.org","method":"GET","uri":"/@killua","status":200,"request_time":0.970,"upstream_response_time":"0.950","upstream_connect_time":"0.000","upstream_header_time":"0.300","bytes":249000,"request_length":100,"content_type":"text/html","cache":""} +{"time":"2026-08-24T15:30:00+02:00","host":"skinbase.org","method":"GET","uri":"/search","status":200,"request_time":0.200,"upstream_response_time":"0.180","upstream_connect_time":"0.000","upstream_header_time":"0.150","bytes":1000,"request_length":80,"content_type":"text/html","cache":""} +not-json diff --git a/tests/fixtures/http-performance/rotation/active.log b/tests/fixtures/http-performance/rotation/active.log new file mode 100644 index 00000000..ffd398b6 --- /dev/null +++ b/tests/fixtures/http-performance/rotation/active.log @@ -0,0 +1,4 @@ +{"time":"2026-08-25T07:50:00+02:00","host":"skinbase.org","method":"GET","uri":"/","status":200,"request_time":0.110,"upstream_response_time":"0.090","upstream_connect_time":"0.000","upstream_header_time":"0.080","bytes":1000,"request_length":80,"content_type":"text/html","cache":""} +{"time":"2026-08-25T07:51:00+02:00","host":"skinbase.org","method":"GET","uri":"/missing","status":404,"request_time":0.040,"upstream_response_time":"0.030","upstream_connect_time":"0.000","upstream_header_time":"0.020","bytes":800,"request_length":70,"content_type":"text/html","cache":""} +{"time":"2026-08-25T07:52:00+02:00","host":"www.skinbase.org","method":"GET","uri":"/","status":200,"request_time":0.200,"upstream_response_time":"0.180","upstream_connect_time":"0.000","upstream_header_time":"0.100","bytes":1000,"request_length":80,"content_type":"text/html","cache":""} +{"time":"2026-08-25T08:10:00+02:00","host":"skinbase.org","method":"GET","uri":"/","status":200,"request_time":0.090,"upstream_response_time":"0.080","upstream_connect_time":"0.000","upstream_header_time":"0.070","bytes":1000,"request_length":80,"content_type":"text/html","cache":""} diff --git a/tests/fixtures/http-performance/rotation/oldest.log b/tests/fixtures/http-performance/rotation/oldest.log new file mode 100644 index 00000000..fa8a0f5a --- /dev/null +++ b/tests/fixtures/http-performance/rotation/oldest.log @@ -0,0 +1,4 @@ +{"time":"2026-08-24T07:50:00+02:00","host":"skinbase.org","method":"GET","uri":"/","status":200,"request_time":0.100,"upstream_response_time":"0.090","upstream_connect_time":"0.000","upstream_header_time":"0.080","bytes":1000,"request_length":80,"content_type":"text/html","cache":""} +{"time":"2026-08-24T08:10:00+02:00","host":"skinbase.org","method":"GET","uri":"/art/53867/light-mark-docks","status":200,"request_time":0.400,"upstream_response_time":"0.380","upstream_connect_time":"0.000","upstream_header_time":"0.200","bytes":10000,"request_length":100,"content_type":"text/html","cache":""} +{"time":"2026-08-24T08:11:00+02:00","host":"skinbase.org","method":"GET","uri":"/missing-old","status":404,"request_time":0.030,"upstream_response_time":"0.020","upstream_connect_time":"0.000","upstream_header_time":"0.010","bytes":700,"request_length":60,"content_type":"text/html","cache":""} +{"time":"2026-08-24T08:12:00+02:00","host":"skinbase.org","method":"GET","uri":"/broken","status":500,"request_time":0.500,"upstream_response_time":"0.480","upstream_connect_time":"0.000","upstream_header_time":"0.200","bytes":200,"request_length":70,"content_type":"text/html","cache":""} diff --git a/tests/fixtures/http-performance/rotation/oldest.log.2.gz b/tests/fixtures/http-performance/rotation/oldest.log.2.gz new file mode 100644 index 00000000..552189ee Binary files /dev/null and b/tests/fixtures/http-performance/rotation/oldest.log.2.gz differ diff --git a/tests/fixtures/http-performance/rotation/rotated.1 b/tests/fixtures/http-performance/rotation/rotated.1 new file mode 100644 index 00000000..b317d34b --- /dev/null +++ b/tests/fixtures/http-performance/rotation/rotated.1 @@ -0,0 +1,4 @@ +{"time":"2026-08-24T23:50:00+02:00","host":"skinbase.org","method":"GET","uri":"/art/3858/similar","status":200,"request_time":0.220,"upstream_response_time":"0.200","upstream_connect_time":"0.000","upstream_header_time":"0.150","bytes":8000,"request_length":90,"content_type":"text/html","cache":""} +{"time":"2026-08-24T23:51:00+02:00","host":"skinbase.org","method":"GET","uri":"/api/art/1/similar-ai","status":502,"request_time":0.250,"upstream_response_time":"0.230","upstream_connect_time":"0.000","upstream_header_time":"0.100","bytes":40,"request_length":80,"content_type":"application/json","cache":""} +{"time":"2026-08-24T23:52:00+02:00","host":"skinbase.org","method":"GET","uri":"/download/artwork/42026","status":499,"request_time":1.800,"upstream_response_time":"1.700","upstream_connect_time":"0.000","upstream_header_time":"0.100","bytes":0,"request_length":90,"content_type":"","cache":""} +{"time":"2026-08-24T23:53:00+02:00","host":"skinbase.org","method":"POST","uri":"/vectors/search","status":422,"request_time":0.050,"upstream_response_time":"0.040","upstream_connect_time":"0.000","upstream_header_time":"0.030","bytes":80,"request_length":100,"content_type":"application/json","cache":""} diff --git a/tests/fixtures/http-performance/sample.log b/tests/fixtures/http-performance/sample.log new file mode 100644 index 00000000..b263d590 --- /dev/null +++ b/tests/fixtures/http-performance/sample.log @@ -0,0 +1,10 @@ +{"time":"2026-08-24T15:10:00+02:00","host":"skinbase.org","method":"GET","uri":"/","status":200,"request_time":0.110,"upstream_response_time":"0.095","upstream_connect_time":"0.000","upstream_header_time":"0.090","bytes":22000,"request_length":120,"content_type":"text/html; charset=utf-8","cache":""} +{"time":"2026-08-24T15:11:00+02:00","host":"skinbase.org","method":"GET","uri":"/academy","status":200,"request_time":0.630,"upstream_response_time":"0.610","upstream_connect_time":"0.000","upstream_header_time":"0.400","bytes":24000,"request_length":140,"content_type":"text/html; charset=utf-8","cache":""} +{"time":"2026-08-24T15:12:00+02:00","host":"skinbase.org","method":"GET","uri":"/academy","status":200,"request_time":0.690,"upstream_response_time":"0.670","upstream_connect_time":"0.000","upstream_header_time":"0.410","bytes":24000,"request_length":140,"content_type":"text/html; charset=utf-8","cache":""} +{"time":"2026-08-24T15:13:00+02:00","host":"skinbase.org","method":"GET","uri":"/favicon.ico","status":200,"request_time":0.004,"upstream_response_time":"-","upstream_connect_time":"-","upstream_header_time":"-","bytes":1500,"request_length":80,"content_type":"image/x-icon","cache":""} +{"time":"2026-08-24T15:14:00+02:00","host":"skinbase.org","method":"GET","uri":"/download/artwork/17776","status":302,"request_time":0.340,"upstream_response_time":"0.100, 0.220","upstream_connect_time":"0.000","upstream_header_time":"0.090, 0.200","bytes":0,"request_length":200,"content_type":"text/html","cache":""} +{"time":"2026-08-24T15:15:00+02:00","host":"skinbase.org","method":"GET","uri":"/missing-page","status":404,"request_time":0.080,"upstream_response_time":"0.070","upstream_connect_time":"0.000","upstream_header_time":"0.060","bytes":8000,"request_length":90,"content_type":"text/html","cache":""} +{"time":"2026-08-24T15:16:00+02:00","host":"skinbase.org","method":"GET","uri":"/@killua","status":200,"request_time":0.970,"upstream_response_time":"0.950","upstream_connect_time":"0.000","upstream_header_time":"0.200","bytes":249000,"request_length":110,"content_type":"text/html","cache":""} +{"time":"2026-08-24T15:17:00+02:00","host":"skinbase.org","method":"GET","uri":"/academy/prompts","status":499,"request_time":1.800,"upstream_response_time":"1.790","upstream_connect_time":"0.000","upstream_header_time":"0.100","bytes":0,"request_length":130,"content_type":"","cache":""} +{"time":"2026-08-24T15:18:00+02:00","host":"skinbase.org","method":"GET","uri":"/explore","status":500,"request_time":0.500,"upstream_response_time":"0.480","upstream_connect_time":"0.000","upstream_header_time":"0.200","bytes":1200,"request_length":100,"content_type":"text/html","cache":""} +this is not json