Skip to content

Horizon: forked processes write their output a whole line at a time - #1

Merged
tevkert merged 1 commit into
tevkert:mainfrom
One-Learning-Community:whole-lines-from-forked-processes
Nov 9, 2026
Merged

tevkert merged 1 commit into
tevkert:mainfrom
One-Learning-Community:whole-lines-from-forked-processes

Conversation

@serpentblade

Copy link
Copy Markdown
Contributor

Forked Horizon workers interleave their job lines in the log. This keeps each line whole.

What happens

Stock Horizon starts each worker with its own pipe; the supervisor reads it and relays what arrives, so lines from different workers never mix. A forked worker writes straight to the stdout it inherited, which every forked process in the tree shares. queue:work writes each job line in three or four pieces (date Job, the dots, then RUNNING, or the run time and DONE with a writeln), so with several workers busy the pieces interleave mid-line:

  2026-11-09 06:28:10 Laravel\Scout\Jobs\MakeSearchable  2026-11-09 06:28:10 Laravel\Scout\Jobs\MakeSearchable ......... ......... 47.27ms ......... DONE

Nothing is lost (Horizon's own job records are complete), but anything that reads the container log line by line gets garbage: log-based job counts, alerts on FAIL, and the like.

The change

  • Support\LineBufferFilter: a write filter that holds output until a newline and passes each complete line on as its own bucket, so each line goes out in one write(). A pipe delivers a write of up to PIPE_BUF in one piece, so the line reaches the log whole. A partial line is held up to 4096 bytes, and whatever is held is passed on when the stream closes.
  • Support\LineBufferedOutput::attachToStdio() appends it to STDOUT and STDERR, which is what Symfony's ConsoleOutput writes to outside Windows. It's called in Wiring::child(), so the master, the supervisor loops and the workers all get it before their command writes anything.
  • Added to Runtime::CLASSES; unit tests in tests/Unit/LineBufferedOutputTest.php. composer test passes.

Measured

A large Laravel 13 app in Docker on PHP 8.4 / Horizon 5.50.1: 2 supervisors, 9 workers, 1,980 jobs (search indexing, tracking events and a class-loading job), run once without and once with the change:

Job lines Mangled
1.0.4 4,686 1,348 (29%)
With this change 4,686 0

Memory and throughput were the same in both runs (600 MB PSS after the mix).

Notes

  • Lines longer than PIPE_BUF can still be split by the kernel, as they could be in any process. Job lines are far shorter.
  • I first hooked CommandStarting from Wiring::child() to reach the command's output. In our forked children the listener was never called, though the kernel's Symfony dispatcher was in place when the child was wired. I didn't get to the bottom of it, so I filtered the streams instead, which doesn't depend on any event. It may be worth a look, since the CommandFinished listener in Wiring::child() goes through the same events.
  • Windows is untouched: there ConsoleOutput reopens php://stdout rather than using STDOUT, and forking doesn't run there anyway.

Thanks for the package. On our app it took Horizon from about 1.5 GB to about 0.6 GB at the same load.

Stock Horizon gives each worker a pipe that its supervisor reads and relays,
so lines from different workers never mix. Forked processes write straight to
the stdout they inherited, which they all share, and queue:work writes each job
line in three or four pieces, so pieces from different workers interleave
mid-line in the container log.

A write filter on STDOUT and STDERR now holds output until a newline and passes
each complete line on as its own write. A pipe delivers a write of up to
PIPE_BUF in one piece, so each line reaches the log whole. A partial line is
held up to 4096 bytes and passed on when the stream closes.

It filters the streams themselves, which are what Symfony's ConsoleOutput
writes to outside Windows, and is attached in Wiring::child() so it is in place
before the command writes anything.
@tevkert

tevkert commented Nov 9, 2026

Copy link
Copy Markdown
Owner

Thanks for this, and for the measurements. Glad the package was useful for you, and the diagnosis is right: filtering the stream fits better than a console event.

While reviewing it I found a few edge cases. GitHub doesn't let me push to a branch of an organization-owned fork, so I opened #2 instead: your commit, unchanged, with mine (d251cd7) on top. Merging it marks this PR as merged too.

  • Exit status: a partial line still held at exit made the process exit 255 and lost the line. PHP invalidates STDOUT before the filter's last flush, so stream_bucket_new() threw. The last bucket is now made against a temporary stream.
  • STDERR is no longer filtered: after an engine fatal error (memory or time limit), PHP stops calling user filters and a filtered stream drops everything, which swallowed Laravel's fatal-error report. Job lines go to STDOUT, so that's all we filter.
  • Scope: only where stdout is shared, meaning forked Horizon processes and shared-log workers. Normal-mode queue:work workers have their own stdio.
  • Forks: a job that forks no longer repeats the half-line its parent held.
  • LineBufferFilter is preloaded (PreloadTest skipped it because of the extends), the line scan is linear, and the comments and README are adjusted. That includes the CommandStarting note: the console kernel reroutes those events itself after boot, outside unit tests.
  • There are tests in real PHP processes for all of the above, including four forked writers sharing one pipe.

If you get a chance to rerun your measurement on #2's branch, I'd be glad to see the numbers. Otherwise shout if anything doesn't sit right. I'll merge once CI is green.

tevkert added a commit that referenced this pull request Nov 9, 2026
Horizon: forked processes write stdout a whole line at a time (builds on #1)
@tevkert
tevkert merged commit 16b7815 into tevkert:main Nov 9, 2026
27 checks passed
tevkert added a commit that referenced this pull request Nov 9, 2026
Forked Horizon processes and shared-log workers write their stdout a whole
line at a time, so job lines from different workers no longer interleave
in the log (#1, #2). CHANGELOG for 1.0.5.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@serpentblade

Copy link
Copy Markdown
Contributor Author

Thanks for the fixes and the quick release. I reran the measurement on the v1.0.5 tag with the same setup as before (PHP 8.4, Horizon 5.50.1, 2 supervisors, 9 workers, the same 1,980 jobs):

Job lines Mangled
1.0.4 4,686 1,348 (29%)
#1 as sent 4,686 0
1.0.5 4,682 0

Every job has its RUNNING line and its DONE line (2,341 of each), and the counts per job class match what was dispatched. The 4 fewer lines come from an event in our app that fires depending on the data, not from anything lost.

Memory and speed are the same as before: 325 MB PSS idle, 602 MB after the mix, 767 MB after the class-loading jobs, no worker restarts and no failed jobs.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants