Logging in requests is very slow

[NiroDeveloper]

Octane Version

2.0.2

Laravel Version

10.15.0

PHP Version

8.1

What server type are you using?

Swoole

Server Version

5.0.3

Database Driver & Version

No response

Description

In my tests i can achieve over 2000 RPS with Laravel Octane and Swoole. But if i add an log message to every request, the Performance drops dramatically to under 100 RPS.

What I have already found out:

• This Bottleneck scales with the length of the log message
• $server->disableOutput() in StartSwooleCommand fixes the problem

This is a critical problem! You can say now that you shouldn't log so much ... however, many error messages with exceptions would immediately paralyze the service.

Steps To Reproduce

• Add Laravel Route
• Add Log Message to Route
• Print some data like Str::random(512)

[Namoshek]

What does your logging configuration look like?

[NiroDeveloper]

@Namoshek

'json'   => [
    'driver'         => 'monolog',
    'level'          => env('LOG_LEVEL', 'debug'),
    'handler'        => StreamHandler::class,
    'formatter'      => JsonFormatter::class,
    'formatter_with' => [
        'includeStacktraces' => true,
    ],
    'with'           => [
        'stream' => 'php://stderr',
    ],
],

stderr so the messages will not be formatted by octane.

[NiroDeveloper]

I found an workaround.

'json'   => [
    'driver'         => 'monolog',
    'level'          => env('LOG_LEVEL', 'debug'),
    'handler'        => ProcessHandler::class,
    'with'           => [
        'command' => 'cat >> /proc/1/fd/1',
    ],
    'formatter'      => JsonFormatter::class,
    'formatter_with' => [
        'includeStacktraces' => true,
    ],
],

[driesvints]

Great that you found a workaround @NiroDeveloper. It does seem you're using a custom logger so I'm not sure this is something we can provide support for sorry.

[NiroDeveloper]

@driesvints This are classes of monolog or wdym with custom logger? What is the recommended way to log on stdout?

[driesvints]

We already have an stderr logger configured here: https://github.com/laravel/laravel/blob/10.x/config/logging.php#L97

Is that not working for you?

[NiroDeveloper]

That is exactly the same configuration (I just added the json formatter). I am assuming that the same problem occurs with this configuration.

[driesvints]

It does seem to be missing the processor. I'm also not sure we extensively tested the JsonFormatter to be used with octane.

[NiroDeveloper]

The processor and JsonFormatter are just the ways how the string will be generated. No matter what string is output and in what format, the problem exists. Explicitly the StreamHandler and 'stream' => 'php://stderr' is the cause of the problem.

[driesvints]

Right. I guess right now, this doesn't play well with Octane. If you want, we'd appreciate a PR to the docs about this 👍

[LauJosefsen]

What is the solution to this? Using the example above with ProcessHandler and cat can result in logs getting intermangled if the server is logging a lot.

    'handler'        => ProcessHandler::class,
    'with'           => [
        'command' => 'cat >> /proc/1/fd/1',
    ],

[NiroDeveloper]

@LauJosefsen I still don't know any good solutions, in my case this workaround works pretty well. Looks like Laravel Octane is not made to write many logs like access logs and the laravel team has no interest in finding a solution.

Maybe another monolog handler is useful for you e.g. SocketHandler or RedisHandler. https://github.com/Seldaek/monolog/blob/main/doc/02-handlers-formatters-processors.md

[LauJosefsen]

@driesvints

This continues to be an issue for us. We are logging quite a bit, and we cannot log to stdout, as Octane will apply some formatting to that.

The workaround provided here causes intermangled logs, so it is not really an option.

Would it be a solution to disable the formatting of stdout with an env variable, or maybe not to do it by default? It is a bit unexpected that a non octane laravel application will not format stdout, but Octane will.

[driesvints]

Hi @LauJosefsen. Yeah maybe we can. Can you send in a PR for Taylor to review?

[NiroDeveloper]

Care my workaround generates endless linux processes! This led to our operating system becoming unusable, until system restart.

@driesvints Logging in octane is still a critical, unstable and undocumented use case, at least the issue should be open so that it gets attention. Maybe there will be someone who knows about it and can fix it better than me.

[driesvints]

Will just reopen this for now. PR's welcome.

[github-actions[bot]]

Thank you for reporting this issue!

As Laravel is an open source project, we rely on the community to help us diagnose and fix issues as it is not possible to research and fix every issue reported to us via GitHub.

If possible, please make a pull request fixing the issue you have described, along with corresponding tests. All pull requests are promptly reviewed by the Laravel team.

Thank you!

[NiroDeveloper]

Here is a further analysis from me on this problem. Looks like the source of the bottleneck is the Symfony Process class or PHP's proc_open that streams into pipes. This has the consequence that log messages from a subprocess cannot be read fast enough, i think the whole concept is reaching its limits here.

There are basically 3 approaches here:

1. Do not send the log messages through octane, instead do a detour such as cat >> /proc/1/fd/1 around the process. https://github.com/laravel/octane/issues/724#issuecomment-1649617729
2. Somehow forward the output unchanged via TTY or shell php swoole-server > /dev/stdout.
3. Analyse this stdout/stderr read bottleneck further in Symfony or PHP.

@LauJosefsen Is your only problem the formatting or also the performance? If only the formatting is your problem, you can log everything to stderr. Octane will just format the stdout messages.

[LauJosefsen]

@NiroDeveloper Thanks for looking into this.

The problem is currently you either can achieve fast logging through the cat >> /proc/1/fd/1 work-around, however the work-around causes logs to be intermangled, as many processes can write to the /proc/1/fd/1 file at the same time.

Not using the work around introduces a 200ms latency bump on our most busy services - defeating the point of Octane.

Logging to stderr is not a problem for us. - I had the assumption that stdout was not experiencing the slowness, but I guess that was a misunderstanding from my side. The comment on stdout vs stderr, was simply that it was unexpected the logs are formatted in an octane application, but not in a non-octane Laravel application. This main issue is the performance penalty of many workers writing to either stdout/stderr at the same time. I am sorry for the confusion :hugs:

I will have a look at the symfony process class.

[NiroDeveloper]

It seems that the stdout and stderr buffer of the pipes are too small which leads to a blocking subprocess. A solution for that would be to read the log message more often by decreasing the usleep here https://github.com/laravel/octane/blob/41051a608eeeaa455d2a0aa14fcdb61500f4cfda/src/Commands/Concerns/InteractsWithServers.php#L48 But decreasing this usleep only ensures that the limit occurs later.

[firecow]

Making this value configurable would be awesome

[LauJosefsen]

It seems that the stdout and stderr buffer of the pipes are too small which leads to a blocking subprocess. A solution for that would be to read the log message more often by decreasing the usleep here

https://github.com/laravel/octane/blob/41051a608eeeaa455d2a0aa14fcdb61500f4cfda/src/Commands/Concerns/InteractsWithServers.php#L48

But decreasing this usleep only ensures that the limit occurs later.

Good finding!

Is it correctly understood the buffers are defined here?

https://github.com/symfony/symfony/blob/7.0/src/Symfony/Component/Process/Process.php#L1426

I.e. 1MB i assume? Do i understand correctly that we have a limit of logging 2MB per second with the current sleep amount?

[NiroDeveloper]

@LauJosefsen I increased the buffer size in the Process class, but without any impact. In my answer, I was thinking more of the pipes that are generated by proc_open, i.e. are stored in the UnixSocket class. I can't say any more about it yet and I don't know yet whether I will analyze it further.

In my tests i was able to generate log output of ~22 MB per Second, but I can't explain to you how this value comes about.

[driesvints]

Given there's no activity here for a month I'm going to close this one now.

[LauJosefsen]

@driesvints

Sorry for the inactivity, I got busy with other tasks.

I just tested a clean Laravel Octane (on FrankenPHP) project with an API route that logs 10k (Log::info(str_repeat('a', 10000));)characters.

I worked it with wrk cli for 20s, first with the default file logger:

➜  ~ wrk -d 60s -c 2 http://127.0.0.1:8000/api
Running 1m test @ http://127.0.0.1:8000/api
  2 threads and 2 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   152.36ms  174.88ms 496.98ms   78.09%
    Req/Sec    15.58      7.97    70.00     91.15%
  1814 requests in 1.00m, 324.18KB read
Requests/sec:     30.22
Transfer/sec:      5.40KB

Then i worked again but with LOG_CHANNEL=stderr

➜  ~ wrk -d 60s -c 2 http://127.0.0.1:8000/api
Running 1m test @ http://127.0.0.1:8000/api
  2 threads and 2 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   580.11ms  189.57ms   1.00s    82.52%
    Req/Sec     0.91      0.49     3.00     78.64%
  206 requests in 1.00m, 36.81KB read
Requests/sec:      3.43
Transfer/sec:     627.87B

I then removed the usleep linked in InteractsWithServers in my vendor folder and tested again.

➜  ~ wrk -d 60s -c 2 http://127.0.0.1:8000/api
Running 1m test @ http://127.0.0.1:8000/api
  2 threads and 2 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   141.06ms  191.39ms   1.02s    80.67%
    Req/Sec   132.33    133.93     0.88k    82.59%
  10396 requests in 1.00m, 1.81MB read
Requests/sec:    172.99
Transfer/sec:     30.91KB

I have not conducted any extensive testing of how much logging throughput can be achieved without the sleep, but it definitely fixes the issue completely for this test.

So am I wondering two things now.

1. Why is this sleep neccessary? Is it to avoid high CPU loads during idle?
2. Can we make it configurable or find another mechanism to empty the stdout and stderr buffers?

I will happily contribute it myself, if we can agree on a solution. :hugs:

[LauJosefsen]

Oups i accidentally pasted the wrong results, now they are correct. Notice the 50x increase in throughput by emptying the buffer more often.