Millions of log lines in PHP, at constant memory

Millions of log lines in PHP, at constant memory

Tópico: Millions of log lines in PHP, at constant memory
Categoria: Tutoriais | Programação & Tecnologia
Idioma Principal: Português (Conteúdo de Tecnologia)

Descrição do Conteúdo / Informações:
-------------------------------------------------------------------------
Laravel 13, Horizon, PostgreSQL 18.

Our product needs to answer a question about a customer's site: which crawler fetched which URL, on which day, and what status code did it get. Not "how many hits yesterday". The cross product.

Why not a log analyzer

We started with GoAccess, which is an excellent tool, and abandoned it. The reason is worth stating precisely because it is the decision the rest of this article follows from.

GoAccess produces a report.json containing panels: top URLs, top user agents, status code distribution, hits per day. Each panel is already aggregated, and no panel is crossed with any other. So it can tell you that Googlebot fetched 40,000 pages, and separately that 3,000 requests returned 404. It cannot tell you whether Googlebot got any of those 404s.

An aggregate you cannot cross is not data. It is a picture of data.

What we needed was a cube: date, hour, bot, URL, status code, with hit counts and bytes. Once that is the requirement, no report-producing tool helps, because the aggregation has to happen on our axes. So the parser is ours.

What one line costs

Thirteen input formats are supported. Seven of them are variations on the common log format and share one engine: GoAccess style format strings compiled into a regex once, then applied per line.

// app/Services/Logs/Parsers/FormatStringLineParser.php
public static function combined(): self
{
return new self('%h %^[%d:%t %z] "%r" %s %b "%R" "%u"', '%d/%b/%Y', '%T', null);
}

public static function amazonS3(): self
{
return new self('%^ %^ [%d:%t %z] %h %^ %^ %^ %^ "%r" %s %^ %b %^ %^ %^ "%R" "%u"', ...);
}

public static function squidNative(): self
{
return new self('%x %^ %h %^/%s %b %m %U %^ %^ %^', null, null, self::EPOCH);
}

%^ means "a field is here, skip it", which is what makes a 17 column S3 line expressible in one string. %z is ours, not GoAccess's: it captures the UTC offset so that every timestamp is normalized to UTC at parse time rather than at query time. Getting that wrong is how a daily report ends up with 25 hours in it twice a year.

The other formats do not fit a format string and get dedicated parsers: Cloudflare JSON, Caddy JSON, Google Cloud Storage CSV, and a W3C parser that is stateful because IIS declares its columns in a #Fields: header partway through the file. That same W3C parser serves CloudFront, whose lines are URL encoded and whose spaces arrive as +.

The measurement

Benchmarked on this machine on 19 August 2026, running the real three stages: parse the line, classify the user agent, normalize the URL. The corpus is synthetic but deliberately hostile to memoization, with 5,000 distinct paths and 240 distinct agent strings.

Lines
File
Time
Throughput
Peak memory

500,000
86.6 MB
5.91 s
84,550 /s
44.5 MB

Two honest caveats. Real production logs measured slower, around 52,000 lines per second, because real user agent strings are longer and messier than generated ones. And a synthetic corpus flatters any parser.

The number that matters is not the throughput. It is that peak memory was 44.5 MB in this run and 44.5 MB in the previous run with a fraction of the cardinality. It does not move, because nothing accumulates. A 2 GB file uses the same 44.5 MB as an 86 MB one, and the job's memory limit is therefore a constant you can reason about instead of a function of what a customer uploads.

The cube, and the upsert that makes partial work safe

Aggregates land in one table whose unique key is the cube itself.

$table->unique([
'project_id', 'date', 'hour', 'bot_token', 'url_hash', 'status_code',
]);

$table->string('bot_token')->default(''); // sentinel, never null
$table->string('url_hash', 64); // sha-256 of the normalized URL

bot_token defaults to an empty string and is never null, because a null inside a unique key means the key stops deduplicating: two rows with a null bot are distinct as far as the index is concerned. PostgreSQL has NULLS NOT DISTINCT to fix that. SQLite, which our tests run on, does not. So the sentinel is the portable answer, and every column in a uniqueness key is NOT NULL.

The write is an additive upsert.

insert into project_log_aggregates (..., hit_count, bytes_transferred, ...)
values (...)
on conflict (project_id, date, hour, bot_token, url_hash, status_code) do update set
hit_count = project_log_aggregates.hit_count + excluded.hit_count,
bytes_transferred = project_log_aggregates.bytes_transferred + excluded.bytes_transferred,
updated_at = excluded.updated_at

Adding rather than replacing is what makes the whole pipeline restartable. A flush that wrote half a buffer, whose keys then reappear in a later flush, is still correct. Two log files from two servers covering the same hour merge instead of overwriting each other. The excluded pseudo-table is portable across PostgreSQL and SQLite, which matters because the tests run on one and production on the other.

Two constraints come with that choice, and both are load bearing.

Intra-batch duplicates have to be impossible, not merely unlikely. PostgreSQL refuses an ON CONFLICT statement that contains the same conflict key twice in one batch. Our buffer is keyed by the cube, so a duplicate cannot exist by construction; deduplication is structural rather than a step someone could forget. The chunk size is 500 rows, which bounds the number of bindings per statement.

Replaying the same file would double the volumes. Addition has no idempotence of its own, so idempotence is enforced upstream, by a SHA-256 of the uploaded file computed server side while the chunks are assembled. The check is in application code rather than a SQL unique index, deliberately: a run that failed must remain re-uploadable.

The bug that ate its own error handler

This one cost us a production incident and it is the most transferable thing in this article.

Real access logs contain bytes that are not valid UTF-8, and sometimes null bytes, because scanners send binary payloads at your server and your server logs the request line. PostgreSQL rejects both with SQLSTATE 22021. Fine: the ingest catches the exception and writes it to the run's error_message column so the customer sees a failure instead of a spinner.

Except that a Laravel QueryException message contains the SQL with its bindings interpolated. So the message about the invalid byte contains the invalid byte. Writing it fails with the identical 22021. And because that write also happens in failed(), the retry fails the same way.

The run stayed in processing forever. The uploaded file had already been purged, correctly, so there was nothing to retry. The interface showed a job in progress that no longer existed.

private function sanitizeErrorMessage(string $message): string
{
$message = str_replace("\0", '', $message);

if (! mb_check_encoding($message, 'UTF-8')) {
$message = mb_convert_encoding($message, 'UTF-8', 'UTF-8');
}

return Str::limit($message, 500);
}

The same scrubbing applies at the other end of the pipeline, in the URL normalizer, which also strips tracking parameters and caps length at 2,048 bytes using mb_strcut so a multibyte character is never sliced in half.

The part worth underlining: SQLite accepts every one of those bytes happily. No test we could have written on the test database would have found this. It is a whole class of defect that is green in CI and fatal in production, and the only defence is knowing it exists.

Queue discipline for a job that cannot be retried

public $tries = 1;
public $timeout = 1800;
// dedicated queue: logs-processing

One attempt, on purpose. A file that was half ingested must never be replayed, because the upsert adds. The dedicated queue exists so that a customer uploading a 2 GB archive cannot starve every other job in the system for half an hour, and it needs its own Horizon supervisor, which in turn means Horizon has to be restarted on deploy or the new code never runs.

The upload itself is chunked and hand written rather than a single multipart POST: 4 MB binary chunks, the SHA-256 accumulated server side as they are assembled, and a 422 on completion that returns the list of missing chunk indexes so the client re-pushes only those. Resumable uploads are not a feature we wanted to build, they are what a 2 GB file on a hotel connection requires.

Retention that keeps the answer and drops the resolution

A cube grows. Ours drops resolution before it drops data.

public const DAILY_AFTER_DAYS = 90;
public const PURGE_AFTER_DAYS = 400;

Past 90 days, the 24 hourly rows of a given day, bot, URL and status collapse into a single row at hour = 0, using the same additive upsert as the ingest, inside one transaction, and the hourly rows are then deleted. Past 400 days, rows go.

This is only safe because no analysis query filters on hour: the column exists for ingest fidelity, not for reporting. Checking that before writing the compaction is the entire difference between a retention job and a data loss incident.

No IP address is stored, and the nuance matters

The cube has no IP column. Nothing in the log services persists a client address, and nothing sends one to a model.

But the parser does read it, and pretending otherwise would be a lie: the common log format is positional, so %h has to be captured for the fields after it to line up. The address exists in memory for the lifetime of one line and is then discarded with it.

That distinction is the honest version of the claim, and it is also the useful one. "We do not process IP addresses" would be false. "No client address is written to disk or leaves the machine" is true, verifiable by looking at the schema, and it is what a customer handing over their server logs actually needs to know.

What we would do differently

•
Reverse DNS verification is still missing. We classify crawlers by user agent, which is trivially spoofable. Verifying that a self declared Googlebot actually comes from Google requires a reverse lookup followed by a forward confirmation, and we have not built it. Until then, our bot attribution is a declared identity, not a verified one, and the interface should say so.

•
The throughput number is machine dependent and we treat it as such. The figure in our own engineering journal was 52,000 lines per second. Re-measuring it for this article gave 84,550 on different hardware with a friendlier corpus. Both are true, neither is "the" number, and a written measurement is an observation with a date rather than a property of the system.

•
Streaming was not the hard part. Reading a file line by line in PHP is a while loop. The hard parts were the byte level hostility of real logs, the portability of one SQL statement across two engines, and deciding what a partially completed ingest is allowed to mean.

Benchmarked 19 August 2026 on a synthetic 500,000 line COMBINED corpus, 86.6 MB, 5,000 distinct paths and 240 distinct user agent strings, running FormatStringLineParser, LogBotRegistry and LogUrlNormalizer in sequence. Peak memory via memory_get_peak_usage. Production figure of 52,000 lines per second measured 21 July 2026 on real access logs.

Originally published at nessflow.com.

I write about how NessFlow is built at nessflow.com/en/engineering.