Add HTTP performance log analyzer (M12.6).

Parse rotated nginx JSON access logs into host/route timings so production hotspots can be measured without ad-hoc one-off scripts.
This commit is contained in:
2026-08-29 12:25:27 +02:00
parent 4ab315e9d7
commit fb560fb7dd
10 changed files with 737 additions and 139 deletions
+261 -19
View File
@@ -10,16 +10,23 @@ namespace App\Support\Http;
* Multi-value upstream timings (retries): use the **sum** of numeric parts * Multi-value upstream timings (retries): use the **sum** of numeric parts
* as the upstream total for that request. "-" and empty → null. * as the upstream total for that request. "-" and empty → null.
* Percentiles use nearest-rank (ceil(p * n), 1-indexed). * 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 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) public function __construct(private readonly HttpUriNormalizer $uris)
{ {
} }
/** /**
* @param string|list<string> $input
* @param array{ * @param array{
* since?: ?string, * since?: ?string,
* until?: ?string,
* min_requests?: int, * min_requests?: int,
* top?: int, * top?: int,
* status?: ?string, * status?: ?string,
@@ -30,28 +37,54 @@ final class HttpPerformanceLogAnalyzer
* } $options * } $options
* @return array<string, mixed> * @return array<string, mixed>
*/ */
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)); $minRequests = max(1, (int) ($options['min_requests'] ?? 1));
$top = max(1, (int) ($options['top'] ?? 20)); $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; $uriFilter = $options['uri'] ?? null;
$hostFilter = isset($options['host']) ? (string) $options['host'] : ''; $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; $skipped = 0;
$linesScanned = 0;
$parseable = 0;
$families = []; $families = [];
$slowest = []; $slowest = [];
$statusCounts = ['4xx' => 0, '5xx' => 0, '499' => 0, 'total' => 0]; $statusCounts = ['4xx' => 0, '5xx' => 0, '499' => 0, 'total' => 0];
$sources = [];
$earliestParseable = null;
$latestParseable = null;
$earliestMatching = null;
$latestMatching = null;
$handle = fopen($file, 'r'); foreach ($files as $file) {
$source = [
'path' => $file,
'gzip' => str_ends_with(strtolower($file), '.gz'),
'lines_scanned' => 0,
'parseable' => 0,
'in_window' => 0,
'error' => null,
];
$handle = $this->openStream($file);
if ($handle === false) { if ($handle === false) {
throw new \RuntimeException('Unable to open performance log: '.$file); $source['error'] = 'unreadable';
$sources[] = $source;
continue;
} }
try { try {
while (($line = fgets($handle)) !== false) { while (($line = fgets($handle)) !== false) {
$linesScanned++;
$source['lines_scanned']++;
$line = trim($line); $line = trim($line);
if ($line === '') { if ($line === '') {
continue; continue;
@@ -64,24 +97,28 @@ final class HttpPerformanceLogAnalyzer
} }
$time = $this->parseTime((string) ($row['time'] ?? '')); $time = $this->parseTime((string) ($row['time'] ?? ''));
if ($since !== null && ($time === null || $time < $since)) {
continue;
}
$requestTime = $this->parseFloat($row['request_time'] ?? null); $requestTime = $this->parseFloat($row['request_time'] ?? null);
if ($requestTime === null) { if ($requestTime === null) {
$skipped++; $skipped++;
continue; 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); $status = (int) ($row['status'] ?? 0);
if ($statusFilter === '5xx' && ($status < 500 || $status > 599)) { if (! $this->statusMatches($status, $statusFilter)) {
continue;
}
if ($statusFilter === '4xx' && ($status < 400 || $status > 499)) {
continue;
}
if ($statusFilter === '499' && $status !== 499) {
continue; continue;
} }
@@ -99,6 +136,12 @@ final class HttpPerformanceLogAnalyzer
continue; 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); $upstreamResponse = $this->parseUpstream($row['upstream_response_time'] ?? null);
$upstreamHeader = $this->parseUpstream($row['upstream_header_time'] ?? null); $upstreamHeader = $this->parseUpstream($row['upstream_header_time'] ?? null);
$bytes = (int) ($row['bytes'] ?? 0); $bytes = (int) ($row['bytes'] ?? 0);
@@ -158,13 +201,16 @@ final class HttpPerformanceLogAnalyzer
'method' => $method, 'method' => $method,
'status' => $status, 'status' => $status,
'request_time' => $requestTime, 'request_time' => $requestTime,
'upstream_response_time' => $upstreamResponse,
]; ];
$slowest[array_key_last($slowest)]['upstream_response_time'] = $upstreamResponse;
} }
} finally { } finally {
fclose($handle); fclose($handle);
} }
$sources[] = $source;
}
usort($slowest, static fn (array $a, array $b): int => $b['request_time'] <=> $a['request_time']); usort($slowest, static fn (array $a, array $b): int => $b['request_time'] <=> $a['request_time']);
$slowest = array_slice($slowest, 0, $top); $slowest = array_slice($slowest, 0, $top);
@@ -213,8 +259,24 @@ final class HttpPerformanceLogAnalyzer
$by404 = array_values(array_filter($summaries, static fn (array $row): bool => ($row['404'] ?? 0) > 0)); $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']); usort($by404, static fn (array $a, array $b): int => $b['404'] <=> $a['404']);
$coverage = $this->coverageReport(
$requestedStart,
$requestedEnd,
$earliestParseable,
$latestParseable,
$earliestMatching,
$latestMatching,
);
return [ return [
'skipped' => $skipped, '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, 'totals' => $statusCounts,
'by_p95' => array_slice($byP95, 0, $top), 'by_p95' => array_slice($byP95, 0, $top),
'by_p99' => array_slice($byP99, 0, $top), 'by_p99' => array_slice($byP99, 0, $top),
@@ -229,6 +291,48 @@ final class HttpPerformanceLogAnalyzer
]; ];
} }
/**
* @param list<string> $paths
* @return list<string>
*/
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<string>
*/
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. * Nearest-rank: rank = ceil(p * n), 1-indexed.
* *
@@ -274,6 +378,135 @@ final class HttpPerformanceLogAnalyzer
return $found ? $sum : null; return $found ? $sum : null;
} }
/**
* @param string|list<string> $input
* @return list<string>
*/
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<string, mixed>
*/
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 private function parseFloat(mixed $value): ?float
{ {
if ($value === null || $value === '' || $value === '-') { if ($value === null || $value === '' || $value === '-') {
@@ -306,7 +539,7 @@ final class HttpPerformanceLogAnalyzer
} }
if (preg_match('/^(\d+)(h|d|m)$/', strtolower($since), $matches) !== 1) { if (preg_match('/^(\d+)(h|d|m)$/', strtolower($since), $matches) !== 1) {
return null; return $this->parseTime($since);
} }
$n = (int) $matches[1]; $n = (int) $matches[1];
@@ -319,4 +552,13 @@ final class HttpPerformanceLogAnalyzer
return $now->sub($interval); return $now->sub($interval);
} }
private function untilInstant(?string $until, \DateTimeImmutable $now): \DateTimeImmutable
{
if ($until === null || $until === '') {
return $now;
}
return $this->parseTime($until) ?? $now;
}
} }
@@ -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.
+60 -10
View File
@@ -3,10 +3,18 @@
declare(strict_types=1); declare(strict_types=1);
/** /**
* Read-only analyzer for /var/log/nginx/skinbase-performance.log * Read-only analyzer for nginx skinbase-performance JSON logs.
* *
* Usage: * Single file (backward compatible):
* php scripts/analyze-http-performance.php --file=/var/log/nginx/skinbase-performance.log --since=24h --top=20 --host=skinbase.org * 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; use App\Support\Http\HttpPerformanceLogAnalyzer;
@@ -14,9 +22,11 @@ use App\Support\Http\HttpUriNormalizer;
require __DIR__.'/../vendor/autoload.php'; require __DIR__.'/../vendor/autoload.php';
$files = [];
$globs = [];
$options = [ $options = [
'file' => '/var/log/nginx/skinbase-performance.log',
'since' => '24h', 'since' => '24h',
'until' => null,
'min_requests' => 1, 'min_requests' => 1,
'top' => 20, 'top' => 20,
'status' => null, 'status' => null,
@@ -31,9 +41,18 @@ foreach (array_slice($argv, 1) as $arg) {
exit(2); exit(2);
} }
[$key, $value] = array_pad(explode('=', substr($arg, 2), 2), 2, '1'); [$key, $value] = array_pad(explode('=', substr($arg, 2), 2), 2, '1');
if ($key === 'file') {
$files[] = $value;
continue;
}
if ($key === 'glob') {
$globs[] = $value;
continue;
}
$map = [ $map = [
'file' => 'file',
'since' => 'since', 'since' => 'since',
'until' => 'until',
'hours' => 'hours',
'min-requests' => 'min_requests', 'min-requests' => 'min_requests',
'top' => 'top', 'top' => 'top',
'status' => 'status', 'status' => 'status',
@@ -48,15 +67,38 @@ foreach (array_slice($argv, 1) as $arg) {
$options[$map[$key]] = $value; $options[$map[$key]] = $value;
} }
$file = (string) $options['file']; if (isset($options['hours']) && is_numeric($options['hours'])) {
if (! is_readable($file)) { $options['since'] = ((int) $options['hours']).'h';
fwrite(STDERR, "Cannot read {$file}\n");
exit(1);
} }
$analyzer = new HttpPerformanceLogAnalyzer(new HttpUriNormalizer()); $analyzer = new HttpPerformanceLogAnalyzer(new HttpUriNormalizer());
$result = $analyzer->analyze($file, [
$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'], 'since' => $options['since'],
'until' => $options['until'],
'min_requests' => (int) $options['min_requests'], 'min_requests' => (int) $options['min_requests'],
'top' => (int) $options['top'], 'top' => (int) $options['top'],
'status' => $options['status'], 'status' => $options['status'],
@@ -64,5 +106,13 @@ $result = $analyzer->analyze($file, [
'host' => $options['host'], 'host' => $options['host'],
'slow_ms' => $options['slow_ms'] !== null ? (float) $options['slow_ms'] : null, '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; echo json_encode($result, JSON_PRETTY_PRINT | JSON_UNESCAPED_SLASHES), PHP_EOL;
@@ -0,0 +1,223 @@
<?php
use App\Support\Http\HttpPerformanceLogAnalyzer;
use App\Support\Http\HttpUriNormalizer;
function rotationDir(): string
{
return dirname(__DIR__, 2).'/fixtures/http-performance/rotation';
}
function analyzerNow(): DateTimeImmutable
{
return new DateTimeImmutable('2026-08-25T08:00:00+02:00');
}
function writeGzFixture(): string
{
$plain = rotationDir().'/oldest.log';
$gz = rotationDir().'/oldest.log.2.gz';
$lines = <<<'JSON'
{"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":""}
JSON;
file_put_contents($plain, $lines."\n");
$gzHandle = gzopen($gz, 'wb');
fwrite($gzHandle, $lines."\n");
gzclose($gzHandle);
return $gz;
}
function rotationFiles(): array
{
return [
rotationDir().'/active.log',
rotationDir().'/rotated.1',
writeGzFixture(),
];
}
function analyzeRotation(array $extra = []): array
{
$analyzer = new HttpPerformanceLogAnalyzer(new HttpUriNormalizer());
return $analyzer->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']);
});
+12
View File
@@ -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
+4
View File
@@ -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":""}
+4
View File
@@ -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":""}
Binary file not shown.
+4
View File
@@ -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":""}
+10
View File
@@ -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