Reduce sleep between reading server logs to improve performance for heavy-logging Laravel application using a stderr/stdout logging driver.

[LauJosefsen]

Hi.

Since the issue has been closed and there is no further activity on #724 , I thought I'd give a proposal on a minimal fix that doesn't break any current applications.

This change makes it possible to change the duration of the usleep that happens after reading the server output pipes in InteractsWithServers. Most users will not need to configure this parameter, but Laravel applications with busy stdout/stderr pipes might.

The change also proposes changing the default from 500ms to 10ms, as 500ms is a potentially large sleep where the server may be trying to write to full pipes.

Benchmarks for a heavily logging Laravel application

I initialized a Laravel application, and installed octane and FrankenPHP. I then added the following endpoint to the api routes.

Route::get('/', function () {
    \Illuminate\Support\Facades\Log::info(str_repeat('a', 10000));
    return [];
});

Default Laravel Octane setup

With the default setup, when working it with 2 connections over a timespan of a minute, I get the following results:

➜  example-app wrk -d 60s -c 2 http://localhost:8000
Running 1m test @ http://localhost:8000
  2 threads and 2 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    31.46ms   50.85ms 390.27ms   84.61%
    Req/Sec   126.53     83.21   350.00     61.67%
  13547 requests in 1.00m, 453.84MB read
Requests/sec:    225.63
Transfer/sec:      7.56MB

Logging with LOG_CHANNEL=stderr and 500ms sleep

I then add the enviroment variable LOG_CHANNEL=stderr with the current laravel/octane^2.0 500ms sleep

➜  example-app wrk -d 60s -c 2 http://localhost:8000
Running 1m test @ http://localhost:8000
  2 threads and 2 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   189.77ms  188.50ms 556.59ms   80.74%
    Req/Sec     7.07      4.29    30.00     69.92%
  828 requests in 1.00m, 27.74MB read
Requests/sec:     13.79
Transfer/sec:    472.95KB

Notice the significant drop in throughput and increase in latency.

Logging with LOG_CHANNEL=stderr and 10ms sleep

Now I introduce the changes in this PR and test again

Running 1m test @ http://localhost:8000
  2 threads and 2 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    32.37ms   51.25ms 332.02ms   84.77%
    Req/Sec   121.79     85.66   350.00     61.43%
  13064 requests in 1.00m, 437.65MB read
Requests/sec:    217.60
Transfer/sec:      7.29MB

As the numbers tell, the application, with these proposed changes, are now back to the numbers of the default application logger.